CLOVER🍀

That was when it all began.

Goアプリケーションをデバッグしたい

これは、なにをしたくて書いたもの?

Goで書かれたアプリケーションをデバッグする方法を、押さえておきたいな、と思いまして。

Goアプリケーションのデバッグ

Goのドキュメントでデバッグについて書かれているのは、こちらのページです。

Debugging Go Code with GDB - The Go Programming Language

gdbデバッグできるようですが、標準のgc Goコンパイラーを使っている場合はDelveというものを使った方が良いとも
書かれています。

GitHub - go-delve/delve: Delve is a debugger for the Go programming language.

デフォルトのコンパイラーはgcのようです。

GDB does not understand Go programs well. The stack management, threading, and runtime contain aspects that differ enough from the execution model GDB expects that they can confuse the debugger and cause incorrect results even when the program is compiled with gccgo. As a consequence, although GDB can be useful in some situations (e.g., debugging Cgo code, or debugging the runtime itself), it is not a reliable debugger for Go programs, particularly heavily concurrent ones. Moreover, it is not a priority for the Go project to address these issues, which are difficult.

環境

今回の環境は、こちらです。

$ go version
go version go1.15.7 linux/amd64

また、デバッグ用のコードも用意しておきましょう。

$ go mod init debug-go-app
go: creating new go.mod: module debug-go-app

go.mod

module debug-go-app

go 1.15

単純なコードを用意。

main.go

package main

import (
    "debug-go-app/sub"
    "fmt"
)

func main() {
    message := sub.GetMessage("World")

    fmt.Println(message)

    languages := []string{"Java", "Go", "Python", "Perl"}

    for _, language := range languages {
        m := sub.GetMessage(language)

        fmt.Println(m)
    }
}

sub/message.go

package sub

import "fmt"

func GetMessage(word string) string {
    return fmt.Sprintf("Hello, %s!!", word)
}

gdbでGoアプリケーションをデバッグする

まずは、gdbデバッグしてみましょう。

どうやら、ビルド時にオプションを付けた方がよさそうです。最適化が効いていると、うまくデバッグできない可能性があるみたいです。

The code generated by the gc compiler includes inlining of function invocations and registerization of variables. These optimizations can sometimes make debugging with gdb harder. If you find that you need to disable these optimizations, build your program using go build -gcflags=all="-N -l".

Debugging Go Code with GDB - The Go Programming Language

というわけで、指示通りgcflags=all='-N -l'を付けてビルド。

$ go build -gcflags=all='-N -l'

アプリケーションを、gdbで起動してみます。

$ gdb ./debug-go-app 
GNU gdb (Ubuntu 9.2-0ubuntu1~20.04) 9.2
Copyright (C) 2020 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
Type "show copying" and "show warranty" for details.
This GDB was configured as "x86_64-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
    <http://www.gnu.org/software/gdb/documentation/>.

For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from ./debug-go-app...
warning: File "/usr/share/go-1.15/src/runtime/runtime-gdb.py" auto-loading has been declined by your `auto-load safe-path' set to "$debugdir:$datadir/auto-load".
To enable execution of this file add
    add-auto-load-safe-path /usr/share/go-1.15/src/runtime/runtime-gdb.py
line to your configuration file "$HOME/.gdbinit".
To completely disable this security protection add
    set auto-load safe-path /
line to your configuration file "$HOME/.gdbinit".
For more information about this security protection see the
"Auto-loading safe path" section in the GDB manual.  E.g., run from the shell:
    info "(gdb)Auto-loading safe path"
(gdb) 

いろいろ言われていますが、警告も混じっていますね。以下の内容で、$HOME/.gdbinitというファイルを作った方が良さそうです。

$HOME/.gdbinit

add-auto-load-safe-path /usr/share/go-1.15/src/runtime/runtime-gdb.py

警告が出なくなりました。

$ gdb ./debug-go-app 
GNU gdb (Ubuntu 9.2-0ubuntu1~20.04) 9.2
Copyright (C) 2020 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
Type "show copying" and "show warranty" for details.
This GDB was configured as "x86_64-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
    <http://www.gnu.org/software/gdb/documentation/>.

For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from ./debug-go-app...
Loading Go Runtime support.

listで関数の内容を表示してみます。

(gdb) list main.main
3   import (
4       "debug-go-app/sub"
5       "fmt"
6   )
7   
8   func main() {
9       message := sub.GetMessage("World")
10  
11      fmt.Println(message)
12

ファイル名と行番号指定で表示。

(gdb) list main.go:5
1   package main
2   
3   import (
4       "debug-go-app/sub"
5       "fmt"
6   )
7   
8   func main() {
9       message := sub.GetMessage("World")
10

サブディレクトリ内のファイル。

(gdb) list sub/message.go:1
1   package sub
2   
3   import "fmt"
4   
5   func GetMessage(word string) string {
6       return fmt.Sprintf("Hello, %s!!", word)
7   }

サブディレクトリ…というかパッケージ内の関数の内容を表示するには…?

(gdb) list sub.GetMessage
Function "sub.GetMessage" not defined.

info functionsで、認識している関数をリストアップしてみます。

(gdb) info functions
All defined functions:

File /path/to/main.go:
    void main.main(void);

File /path/to/sub/message.go:
    void debug-go-app/sub.GetMessage(string, string);

File /usr/lib/go-1.15/src/errors/errors.go:
    void errors.(*errorString).Error;
    void errors.New(string, error);

File /usr/lib/go-1.15/src/errors/wrap.go:
    void errors.init(void);

〜省略〜

よく見ると、自分が作った関数が混じっています。

こうですね。

(gdb) list debug-go-app/sub.GetMessage
1   package sub
2   
3   import "fmt"
4   
5   func GetMessage(word string) string {
6       return fmt.Sprintf("Hello, %s!!", word)
7   }

runでプログラムの実行。

(gdb) run
Starting program: /path/to/debug-go-app 
[New LWP 26218]
[New LWP 26219]
[New LWP 26220]
[New LWP 26221]
Hello, World!!
Hello, Java!!
Hello, Go!!
Hello, Python!!
Hello, Perl!!
[LWP 26221 exited]
[LWP 26220 exited]
[LWP 26219 exited]
[LWP 26218 exited]
[Inferior 1 (process 26217) exited normally]

breakで、指定の関数にブレークポイントを付けられます。

(gdb) break debug-go-app/sub.GetMessage
Breakpoint 1 at 0x4ba6a0: file /path/to/sub/message.go, line 5.

実行すると、ブレークポイントの場所で止まります。

(gdb) run
Starting program: /path/to/debug-go-app 
[New LWP 27081]
[New LWP 27082]
[New LWP 27083]
[New LWP 27084]
[New LWP 27085]

Thread 1 "debug-go-app" hit Breakpoint 1, debug-go-app/sub.GetMessage (word="World", Python Exception <class 'OverflowError'> signed integer is greater than maximum: 
~r1=) at /path/to/sub/message.go:5
5   func GetMessage(word string) string {

printまたはpで、変数の内容を表示。

(gdb) p word
$1 = "World"


(gdb) print word
$2 = "World"

btスタックトレースの表示。

(gdb) bt
#0  debug-go-app/sub.GetMessage (word="World", Python Exception <class 'OverflowError'> signed integer is greater than maximum: 
~r1=) at /path/to/sub/message.go:5
#1  0x00000000004ba82b in main.main () at /path/to/main.go:9

continueで再開します。

(gdb) continue
Continuing.
Hello, World!!

Thread 1 "debug-go-app" hit Breakpoint 1, debug-go-app/sub.GetMessage (word="Java", ~r1=<error reading variable: Cannot access memory at address 0x1>)
    at /path/to/sub/message.go:5
5   func GetMessage(word string) string {

nextで1行ずつ進めていきます。

(gdb) next
6       return fmt.Sprintf("Hello, %s!!", word)
(gdb) next
main.main () at /path/to/main.go:18
18          fmt.Println(m)
(gdb) next
Hello, Java!!
15      for _, language := range languages {
(gdb) next
16          m := sub.GetMessage(language)
(gdb) next

Thread 1 "debug-go-app" hit Breakpoint 1, debug-go-app/sub.GetMessage (word="Go", ~r1=<error reading variable: Cannot access memory at address 0x1>)
    at /path/to/sub/message.go:5
5   func GetMessage(word string) string {
(gdb) next
6       return fmt.Sprintf("Hello, %s!!", word)
(gdb) next
main.main () at /path/to/main.go:18
18          fmt.Println(m)

現在のブレークポイントの一覧は、info breakpointsで表示できます。

(gdb) info breakpoints
Num     Type           Disp Enb Address            What
1       breakpoint     keep y   0x00000000004ba6a0 in debug-go-app/sub.GetMessage at /paht/to/sub/message.go:5
    breakpoint already hit 3 times

deleteで、指定の番号のブレークポイントを削除できます。

(gdb) delete 1

ブレークポイントがなくなりました。

(gdb) info breakpoints
No breakpoints or watchpoints.

再開して、終了。

(gdb) continue
Continuing.
Hello, Go!!
Hello, Python!!
Hello, Perl!!
Couldn't get registers: そのようなプロセスはありません.
Couldn't get registers: そのようなプロセスはありません.
(gdb) [LWP 27085 exited]
[LWP 27084 exited]
[LWP 27083 exited]
[LWP 27082 exited]
[LWP 27081 exited]
[Inferior 1 (process 27077) exited normally]

ビルドした結果は、1度削除しておきます。

$ rm debug-go-app

DelveでGoアプリケーションをデバッグする

次は、DelveでGoアプリケーションをデバッグしてみましょう。

GitHub - go-delve/delve: Delve is a debugger for the Go programming language.

インストール方法は、こちらを参照。

delve/install.md at master · go-delve/delve · GitHub

Goプロジェクト外のディレクトリで、以下のコマンドを実行してインストール。

$ GO111MODULE=on go get github.com/go-delve/delve/cmd/dlv

dlvというコマンドがインストールされました。今回扱うDelveは、1.6.0です。

$ dlv version
Delve Debugger
Version: 1.6.0
Build: $Id: 8cc9751909843dd55a46e8ea2a561544f70db34d $

というわけで、以降はこちらのドキュメントを見ながらDelveを使っていきましょう。

delve/Documentation at v1.6.0 · go-delve/delve · GitHub

使い方は、こちらを見るとよさそうです。

delve/dlv.md at v1.6.0 · go-delve/delve · GitHub

Delveは、サブコマンドを使って実行するようです。たとえば、以下のようなサブコマンドがあります(全部は載せていません)。

まずはdebugが基本かな?と思うので、debugサブコマンドでmain.goを指定して実行。

$ dlv debug main.go 
Type 'help' for list of commands.
(dlv) 

helpと入力するとコマンドが見れるというので、ヘルプを見てみましょう。

(dlv) help
The following commands are available:

Running the program:
    call ------------------------ Resumes process, injecting a function call (EXPERIMENTAL!!!)
    continue (alias: c) --------- Run until breakpoint or program termination.
    next (alias: n) ------------- Step over to next source line.
    rebuild --------------------- Rebuild the target executable and restarts it. It does not work if the executable was not built by delve.
    restart (alias: r) ---------- Restart process.
    step (alias: s) ------------- Single step through program.
    step-instruction (alias: si)  Single step a single cpu instruction.
    stepout (alias: so) --------- Step out of the current function.

Manipulating breakpoints:
    break (alias: b) ------- Sets a breakpoint.
    breakpoints (alias: bp)  Print out info for active breakpoints.
    clear ------------------ Deletes breakpoint.
    clearall --------------- Deletes multiple breakpoints.
    condition (alias: cond)  Set breakpoint condition.
    on --------------------- Executes a command when a breakpoint is hit.
    trace (alias: t) ------- Set tracepoint.

Viewing program variables and memory:
    args ----------------- Print function arguments.
    display -------------- Print value of an expression every time the program stops.
    examinemem (alias: x)  Examine memory:
    locals --------------- Print local variables.
    print (alias: p) ----- Evaluate an expression.
    regs ----------------- Print contents of CPU registers.
    set ------------------ Changes the value of a variable.
    vars ----------------- Print package variables.
    whatis --------------- Prints type of an expression.

Listing and switching between threads and goroutines:
    goroutine (alias: gr) -- Shows or changes current goroutine
    goroutines (alias: grs)  List program goroutines.
    thread (alias: tr) ----- Switch to the specified thread.
    threads ---------------- Print out info for every traced thread.

Viewing the call stack and selecting frames:
    deferred --------- Executes command in the context of a deferred call.
    down ------------- Move the current frame down.
    frame ------------ Set the current frame, or execute command on a different frame.
    stack (alias: bt)  Print stack trace.
    up --------------- Move the current frame up.

Other commands:
    config --------------------- Changes configuration parameters.
    disassemble (alias: disass)  Disassembler.
    edit (alias: ed) ----------- Open where you are in $DELVE_EDITOR or $EDITOR
    exit (alias: quit | q) ----- Exit the debugger.
    funcs ---------------------- Print list of functions.
    help (alias: h) ------------ Prints the help message.
    libraries ------------------ List loaded dynamic libraries
    list (alias: ls | l) ------- Show source code.
    source --------------------- Executes a file containing a list of delve commands
    sources -------------------- Print list of source files.
    types ---------------------- Print list of types

Type help followed by a command for full documentation.

この内容は、こちらのページでも見ることができます。

delve/Documentation/cli at v1.6.0 · go-delve/delve · GitHub

関数の一覧を表示するには、funcsで。

(dlv) funcs

Go自体の関数も大量に現れますが、自分が作成した関数もその中に含まれています。

debug-go-app/sub.GetMessage

...

main.main

正規表現で絞り込むことも可能です。

(dlv) funcs ^main.*
main.main


(dlv) funcs ^debug-go.+
debug-go-app/sub.GetMessage

ソースファイルの一覧の場合は、`sourcesで。

(dlv) sources
/path/to/main.go
/path/to/sub/message.go
/usr/lib/go-1.15/src/errors/errors.go
/usr/lib/go-1.15/src/errors/wrap.go
/usr/lib/go-1.15/src/fmt/doc.go
/usr/lib/go-1.15/src/fmt/errors.go
/usr/lib/go-1.15/src/fmt/format.go
/usr/lib/go-1.15/src/fmt/print.go
/usr/lib/go-1.15/src/fmt/scan.go

〜省略〜


(dlv) sources main.go|message.go
/path/to/main.go
/path/to/sub/message.go

では、ブレークポイントをつけましょう。ヘルプを見てみます。

(dlv) help break
Sets a breakpoint.

    break [name] <linespec>

See $GOPATH/src/github.com/go-delve/delve/Documentation/cli/locspec.md for the syntax of linespec.

See also: "help on", "help cond" and "help clear"

breakの指定の方法は、以下のドキュメントを見るとよさそうです。

delve/locspec.md at v1.6.0 · go-delve/delve · GitHub

いくつか例を挙げてみます。

関数の開始行を指定する方法、ファイルの行数で指定する方法。どちらも同じ位置を指定しています。

(dlv) break debug-go-app/sub.GetMessage:0
Breakpoint 1 set at 0x4ba6b8 for debug-go-app/sub.GetMessage() ./sub/message.go:5


(dlv) break sub/message.go:5
Breakpoint 1 set at 0x4ba6b8 for debug-go-app/sub.GetMessage() ./sub/message.go:5

ブレークポイントを付けたら、nextまたはnで進めます。

(dlv) next
> debug-go-app/sub.GetMessage() ./sub/message.go:5 (hits goroutine(1):1 total:1) (PC: 0x4ba6b8)
     1: package sub
     2: 
     3: import "fmt"
     4: 
=>   5:  func GetMessage(word string) string {
     6:     return fmt.Sprintf("Hello, %s!!", word)
     7: }

次の行へ。

(dlv) n
> debug-go-app/sub.GetMessage() ./sub/message.go:6 (PC: 0x4ba6da)
     1: package sub
     2: 
     3: import "fmt"
     4: 
     5: func GetMessage(word string) string {
=>   6:      return fmt.Sprintf("Hello, %s!!", word)
     7: }

printまたはpで、変数の内容を表示。

(dlv) p word
"World"


(dlv) print word
"World"

stackまたはbtスタックトレースの表示。

(dlv) stack
0  0x00000000004ba6da in debug-go-app/sub.GetMessage
   at ./sub/message.go:6
1  0x00000000004ba82b in main.main
   at ./main.go:9
2  0x000000000043b40f in runtime.main
   at /usr/lib/go-1.15/src/runtime/proc.go:204
3  0x000000000046d8c1 in runtime.goexit
   at /usr/lib/go-1.15/src/runtime/asm_amd64.s:1374


(dlv) bt
0  0x00000000004ba6da in debug-go-app/sub.GetMessage
   at ./sub/message.go:6
1  0x00000000004ba82b in main.main
   at ./main.go:9
2  0x000000000043b40f in runtime.main
   at /usr/lib/go-1.15/src/runtime/proc.go:204
3  0x000000000046d8c1 in runtime.goexit
   at /usr/lib/go-1.15/src/runtime/asm_amd64.s:1374

少し進めてみましょう。

(dlv) n
> main.main() ./main.go:9 (PC: 0x4ba82b)
Values returned:
    ~r1: "Hello, World!!"

     4:     "debug-go-app/sub"
     5:     "fmt"
     6: )
     7: 
     8: func main() {
=>   9:      message := sub.GetMessage("World")
    10: 
    11:     fmt.Println(message)
    12: 
    13:     languages := []string{"Java", "Go", "Python", "Perl"}
    14: 
(dlv) n
> main.main() ./main.go:11 (PC: 0x4ba83f)
     6: )
     7: 
     8: func main() {
     9:     message := sub.GetMessage("World")
    10: 
=>  11:      fmt.Println(message)
    12: 
    13:     languages := []string{"Java", "Go", "Python", "Perl"}
    14: 
    15:     for _, language := range languages {
    16:         m := sub.GetMessage(language)

continueまたはcで、一気に進めることもできます。この場合、次のブレークポイントで停止します(ブレークポイントがなければ
プログラムが終了します)。

(dlv) c
Hello, World!!
> debug-go-app/sub.GetMessage() ./sub/message.go:5 (hits goroutine(1):2 total:2) (PC: 0x4ba6b8)
     1: package sub
     2: 
     3: import "fmt"
     4: 
=>   5:  func GetMessage(word string) string {
     6:     return fmt.Sprintf("Hello, %s!!", word)
     7: }


(dlv) continue
Hello, Java!!
> debug-go-app/sub.GetMessage() ./sub/message.go:5 (hits goroutine(1):3 total:3) (PC: 0x4ba6b8)
     1: package sub
     2: 
     3: import "fmt"
     4: 
=>   5:  func GetMessage(word string) string {
     6:     return fmt.Sprintf("Hello, %s!!", word)
     7: }

現在つけているブレークポイントは、breakpointsで確認できます。…なんかエラー出てますが。

(dlv) breakpoints
Breakpoint runtime-fatal-throw at 0x438d60 for runtime.fatalthrow() /usr/lib/go-1.15/src/runtime/panic.go:1162 (0)
Breakpoint unrecovered-panic at 0x438de0 for runtime.fatalpanic() /usr/lib/go-1.15/src/runtime/panic.go:1189 (0)
    print runtime.curg._panic.arg
Breakpoint 1 at 0x4ba6b8 for debug-go-app/sub.GetMessage() ./sub/message.go:5 (3)

ブレークポイントを削除するには、clearブレークポイントの番号を指定します。

(dlv) clear 1
Breakpoint 1 cleared at 0x4ba6b8 for debug-go-app/sub.GetMessage() ./sub/message.go:5

ブレークポイントがなくなったので、continueで最後まで実行して終了。

(dlv) c
Hello, Go!!
Hello, Python!!
Hello, Perl!!
Process 16021 has exited with status 0

ブレークポイントを関数につける場合は、行番号は省略できます。main.mainにつけてみましょう。

$ dlv debug main.go 
Type 'help' for list of commands.
(dlv) break main.main
Breakpoint 1 set at 0x4ba7fb for main.main() ./main.go:8

ステップ実行。

(dlv) n
> main.main() ./main.go:8 (hits goroutine(1):1 total:1) (PC: 0x4ba7fb)
     3: import (
     4:     "debug-go-app/sub"
     5:     "fmt"
     6: )
     7: 
=>   8:  func main() {
     9:     message := sub.GetMessage("World")
    10: 
    11:     fmt.Println(message)
    12: 
    13:     languages := []string{"Java", "Go", "Python", "Perl"}
(dlv) n
> main.main() ./main.go:9 (PC: 0x4ba812)
     4:     "debug-go-app/sub"
     5:     "fmt"
     6: )
     7: 
     8: func main() {
=>   9:      message := sub.GetMessage("World")
    10: 
    11:     fmt.Println(message)
    12: 
    13:     languages := []string{"Java", "Go", "Python", "Perl"}
    14:

また、stepで関数内にステップインすることができます。

(dlv) step
> debug-go-app/sub.GetMessage() ./sub/message.go:5 (PC: 0x4ba6b8)
     1: package sub
     2: 
     3: import "fmt"
     4: 
=>   5:  func GetMessage(word string) string {
     6:     return fmt.Sprintf("Hello, %s!!", word)
     7: }

関数から呼び出し元に戻るには、stepoutで。

(dlv) stepout
> main.main() ./main.go:9 (PC: 0x4ba82b)
Values returned:
    ~r1: "Hello, World!!"

     4:     "debug-go-app/sub"
     5:     "fmt"
     6: )
     7: 
     8: func main() {
=>   9:      message := sub.GetMessage("World")
    10: 
    11:     fmt.Println(message)
    12: 
    13:     languages := []string{"Java", "Go", "Python", "Perl"}
    14: 

ブレークポイントを削除して終了。

(dlv) clear 1
Breakpoint 1 cleared at 0x4ba7fb for main.main() ./main.go:8
(dlv) c
Hello, World!!
Hello, Java!!
Hello, Go!!
Hello, Python!!
Hello, Perl!!
Process 17217 has exited with status 0

execも試してみましょう。

delve/dlv_exec.md at v1.6.0 · go-delve/delve · GitHub

説明を見ると、こちらもgdbの時と同じくビルド時に最適化を無効にした方がよいみたいです。

$ go build -gcflags="all=-N -l"

ビルド済みのバイナリを指定して、dlv exec。起動後は、debugと変わりません。

$ dlv exec ./debug-go-app 
Type 'help' for list of commands.
(dlv) break debug-go-app/sub.GetMessage
Breakpoint 1 set at 0x4ba6b8 for debug-go-app/sub.GetMessage() ./sub/message.go:5
(dlv) n
> debug-go-app/sub.GetMessage() ./sub/message.go:5 (hits goroutine(1):1 total:1) (PC: 0x4ba6b8)
     1: package sub
     2: 
     3: import "fmt"
     4: 
=>   5:  func GetMessage(word string) string {
     6:     return fmt.Sprintf("Hello, %s!!", word)
     7: }

他のGoアプリケーションでも試せないでしょうか?Terraformを使ってみましょう。

$ terraform version
Terraform v0.14.6


$ which terraform
/usr/local/bin/terraform

Terraformに対して、dlv execしてみます。

$ dlv exec /usr/local/bin/terraform version
Type 'help' for list of commands.
(dlv) 

デバッグセッションが始まり、ブレークポイントはつけられるものの、関数の内容などが表示されません。

(dlv) break main.main
Breakpoint 1 set at 0x221fbaf for main.main() /home/circleci/project/project/main.go:39


(dlv) n
> main.main() /home/circleci/project/project/main.go:39 (hits goroutine(1):1 total:1) (PC: 0x221fbaf)
Warning: debugging optimized function


(dlv) n
> main.main() /home/circleci/project/project/main.go:41 (PC: 0x221fbbd)
Warning: debugging optimized function

これだと、ちょっとデバッグは厳しいですね…。

試しに、自分で書いたGoアプリケーションでビルド時のオプションを指定せずにビルドしてみましょう。

$ go build

特に問題なくデバッグできました。

$ dlv exec ./debug-go-app 
Type 'help' for list of commands.
(dlv) break main.main
Breakpoint 1 set at 0x49ab78 for main.main() ./main.go:8
(dlv) n
> main.main() ./main.go:8 (hits goroutine(1):1 total:1) (PC: 0x49ab78)
Warning: debugging optimized function
     3: import (
     4:     "debug-go-app/sub"
     5:     "fmt"
     6: )
     7: 
=>   8:  func main() {
     9:     message := sub.GetMessage("World")
    10: 
    11:     fmt.Println(message)
    12: 
    13:     languages := []string{"Java", "Go", "Python", "Perl"}

ということは、Terraformはビルド時に最適化していそうですね。

terraform/build.sh at v0.14.6 · hashicorp/terraform · GitHub

同じオプションを指定すると、見事にデバッグできなくなりました。

$ go build -ldflags='-s -w'
$ dlv exec ./debug-go-app
could not launch process: could not open debug info

ちょっとTerraformの時とは動きが違いますが…。

まあ、ビルド済みのGoアプリケーションがいつもデバッグできるとは思わない方がいい、ということですね。

エディタのプラグインもあるようです。

delve/EditorIntegration.md at v1.6.0 · go-delve/delve · GitHub

単独のUIとしては、こちら。

GitHub - aarzilli/gdlv: GUI frontend for Delve

まとめ

Goアプリケーションを、gdbおよびDelveでデバッグしてみました。

慣れればデバッグできるようになるのかなぁとは思いますが、fmt.Printlnあたりでデバッグしていることが自分は多そうな気がします。

まあ、覚えておいて損はないでしょう。

ApacheのMPMを設定を確認する

これは、なにをしたくて書いたもの?

ApacheのMPMの設定…接続数やプロセス数、スレッド数まわりの設定をちょいちょい見る割には覚えていられないので、
1度ちゃんと見ておこうかなということで。

環境

今回の環境は、こちら。

$ lsb_release -a
No LSB modules are available.
Distributor ID: Ubuntu
Description:    Ubuntu 20.04.2 LTS
Release:    20.04
Codename:   focal


$ uname -srvmpio
Linux 5.4.0-65-generic #73-Ubuntu SMP Mon Jan 18 17:25:17 UTC 2021 x86_64 x86_64 x86_64 GNU/Linux

Ubuntu Linux 20.04 LTSです。

こちらにApacheをインストールします。

$ sudo apt install apache2

起動。

$ sudo systemctl enable apache2
$ sudo systemctl start apache2

Apache 2.4.41がインストールされたようです。

$ apachectl -V
Server version: Apache/2.4.41 (Ubuntu)
Server built:   2020-08-12T19:46:17
Server's Module Magic Number: 20120211:88
Server loaded:  APR 1.6.5, APR-UTIL 1.6.1
Compiled using: APR 1.6.5, APR-UTIL 1.6.1
Architecture:   64-bit
Server MPM:     event
  threaded:     yes (fixed thread count)
    forked:     yes (variable process count)
Server compiled with....
 -D APR_HAS_SENDFILE
 -D APR_HAS_MMAP
 -D APR_HAVE_IPV6 (IPv4-mapped addresses enabled)
 -D APR_USE_SYSVSEM_SERIALIZE
 -D APR_USE_PTHREAD_SERIALIZE
 -D SINGLE_LISTEN_UNSERIALIZED_ACCEPT
 -D APR_HAS_OTHER_CHILD
 -D AP_HAVE_RELIABLE_PIPED_LOGS
 -D DYNAMIC_MODULE_LIMIT=256
 -D HTTPD_ROOT="/etc/apache2"
 -D SUEXEC_BIN="/usr/lib/apache2/suexec"
 -D DEFAULT_PIDLOG="/var/run/apache2.pid"
 -D DEFAULT_SCOREBOARD="logs/apache_runtime_status"
 -D DEFAULT_ERRORLOG="logs/error_log"
 -D AP_TYPES_CONFIG_FILE="mime.types"
 -D SERVER_CONFIG_FILE="apache2.conf"

デフォルトのMPMは、eventのようですね。

Server MPM:     event
  threaded:     yes (fixed thread count)
    forked:     yes (variable process count)

これで、Apacheの用意はできました。

ApacheのMPMの種類とドキュメント

ApacheのMPMというのは、Multi-Processing Modulesの略です。ホストのポートにバインドしてリクエストを受け付け、
リクエストを処理するために子にディスパッチするモジュールのことを言います。

Apache HTTP Server 2.0 extends this modular design to the most basic functions of a web server. The server ships with a selection of Multi-Processing Modules (MPMs) which are responsible for binding to network ports on the machine, accepting requests, and dispatching children to handle the requests.

Multi-Processing Modules (MPMs) - Apache HTTP Server Version 2.4

どのMPMがデフォルトで使われるかは環境によって決まっているようですが、UnixライクなOSだとprefork、worker、eventのどれかに
なるようですね。

自分の環境だと、eventになりました、と。

netware、os2、winntというMPMもありますが、こちらは今回は置いておきましょう。

worker、event、preforkの各MPMの説明のサマリーを見てみます。今のデフォルトのMPMを見るとevent、worker、preforkの順が
正解な気がしますが、event、workerの内容を見ていると先にworkerを見た方がよい気がしたので。

worker MPMは、マルチプロセスサーバー、マルチスレッドサーバーのハイブリッドな実装です。スレッドを使用することで
プロセスベースのサーバーよりも少ないリソースで多くのリクエストを処理できます。ただ、それぞれが多くのスレッドを管理する
プロセス自体を複数持つことで安定性を保っています。

This Multi-Processing Module (MPM) implements a hybrid multi-process multi-threaded server. By using threads to serve requests, it is able to serve a large number of requests with fewer system resources than a process-based server. However, it retains much of the stability of a process-based server by keeping multiple processes available, each with many threads.

worker - Apache HTTP Server Version 2.4

なので、マルチプロセスサーバーとマルチスレッドサーバーのハイブリッドなわけですね。このmpmで重要なディレクティブは
各プロセスごとのスレッド数をコントロールするThreadsPerChild、それから起動できる最大スレッド数をコントロールする

MaxRequestWorkersのようです。

event MPMは、リスナースレッドにいくつかの処理を渡すことでワーカースレッドを開放し、より多くのリクエストを処理できるように
設計されたMPMです。

The event Multi-Processing Module (MPM) is designed to allow more requests to be served simultaneously by passing off some processing work to the listeners threads, freeing up the worker threads to serve new requests.

event - Apache HTTP Server Version 2.4

設定はworker MPMほぼ同じなのですが、AsyncRequestWorkerFactorというディレクティブが導入されており、こちらで
プロセスごとに受け入れられる接続数をコントロールできます。

prefork MPMは、その名の通りプリフォークなWebサーバーです。親プロセスが実際にリクエストを処理する子プロセスを管理する
モデルです。Apacheに組み込むモジュールやライブラリにスレッドセーフではないものが含まれている場合、互換性のために
使用するような位置づけです。また、リクエストがプロセス単位で分離されているので、あるリクエストが他のリクエストに
影響を与えることはありません。最も重要なディレクティブはMaxRequestWorkers(以前はMaxClientsと呼ばれていたもの)です。

prefork - Apache HTTP Server Version 2.4

MPMに関する共通的なディレクトティブは、こちらに書かれています。

mpm_common - Apache HTTP Server Version 2.4

各MPMの概要は、ざっくりこんな感じですね。

MPMを設定する

これらのMPMの設定を行うことで、Apacheで受け付けられる接続数、そしてリクエストを処理するのに使うプロセス数やスレッド数を
設定するわけですが、これを1度整理したいなと。

各MPMごとに、ドキュメントを読んで書いていきます。

worker MPM

まずはworker MPMの設定を見ていきましょう。

worker - Apache HTTP Server Version 2.4

ディレクティブ名 説明
ThreadsPerChild プロセスごとに生成するスレッド数
ThreadLimit プロセスごとに持てるスレッド数の上限 (ThreadsPerChildと同じ、もしくは大きい値にする)
StartServers 最初に起動するプロセス数
MaxRequestWorkers 同時に処理できる最大数(各プロセスごとのスレッド数の和の上限)
ServerLimit プロセス数の上限(MaxRequestWorkers / ThreadsPerChild より大きい値である必要がある)
MinSpareThreads 待機スレッドの最少数
MaxSpareThreads 待機スレッドの最大数(MinSpareThreadsThreadsPerChildの和に等しい、もしくは大きい値である必要がある)

Serverがプロセスに関する設定を指し、Threadがスレッドに関する設定を指す、と見ていけば良さそうです。

基本的には、こちらに書かれている内容です。

mpm_common - Apache HTTP Server Version 2.4

なお、プロセス数の指定するディレクティブがありませんが、MaxRequestWorkersの値をThreadsPerChildで割った値で算出されます。

Ubuntu Linux 20.04 LTS/Apache 2.4.41での、worker MPMのデフォルト設定はこちらです。

/etc/apache2/mods-available/mpm_worker.conf

<IfModule mpm_worker_module>
    StartServers             2
    MinSpareThreads      25
    MaxSpareThreads      75
    ThreadLimit          64
    ThreadsPerChild      25
    MaxRequestWorkers     150
    MaxConnectionsPerChild   0
</IfModule>

MaxConnectionsPerChildというのは、各プロセスが処理するリクエスト数です。0以外の値を指定している場合、
プロセスはMaxConnectionsPerChildで指定された数だけリクエストを処理すると、プロセスが終了します。

MaxConnectionsPerChild Directive

メモリリーク回避のために使われ、サーバープロセスを作り直したい場合に使う感じですね。

0の場合、プロセスはリクエストの処理数で終了しなくなります。

あと、ServerLimitは書かれていませんね。worker MPM、もしくはevent MPMの場合、デフォルト値は16です。

ServerLimit Directive

event MPM

event MPMの設定は、worker MPMとほぼ同じです。AsyncRequestWorkerFactorが増えるだけですね。

event - Apache HTTP Server Version 2.4

ディレクティブ名 説明
AsyncRequestWorkerFactor プロセスごとの同時接続数の制限値
ThreadsPerChild プロセスごとに生成するスレッド数
ThreadLimit プロセスごとに持てるスレッド数の上限 (ThreadsPerChildと同じ、もしくは大きい値にする)
StartServers 最初に起動するプロセス数
MaxRequestWorkers 同時に処理できる最大数(各プロセスごとのスレッド数の和の上限)
ServerLimit プロセス数の上限(MaxRequestWorkers / ThreadsPerChild より大きい値である必要がある)
MinSpareThreads 待機スレッドの最少数
MaxSpareThreads 待機スレッドの最大数(MinSpareThreadsThreadsPerChildの和に等しい、もしくは大きい値である必要がある)

event MPMは、一部の接続を非同期で処理します。このケースでは、ワーカースレッドは必要に応じて短時間だけ割り当てられ、
その他のケースだと接続ごとにひとつのワーカースレッドが使用されます。ワーカースレッドを使い尽くした場合でも非同期処理が
できるように、非同期処理用のワーカースレッドをどのくらい用意するかという設定です。

event MPMがどのくらいの接続数を扱えるかは、以下に計算式が書かれています。

AsyncRequestWorkerFactor Directive

各プロセスは、接続数が以下の値よりも低ければ、新しい接続を受け付けます。

ThreadsPerChild + (AsyncRequestWorkerFactor × アイドル状態のワーカースレッド数)

アイドル状態のワーカースレッドの平均値がわかる場合、全プロセスでの最大接続数は以下の式で算出できます。

ThreadsPerChild +( AsyncRequestWorkerFactor × アイドル状態のワーカースレッド数)) × ServerLimit

デフォルトではAsyncRequestWorkerFactorの値は2なので、アイドル状態のワーカースレッドの2倍、非同期用のスレッドとして
扱えることになるわけですね。
※ なのですが、この後で試してみたら(後述)、ちょっとよくわからなくなりました…

Ubuntu Linux 20.04 LTS/Apache 2.4.41での、event MPMのデフォルト設定はこちらです。

/etc/apache2/mods-available/mpm_event.conf

<IfModule mpm_event_module>
    StartServers             2
    MinSpareThreads      25
    MaxSpareThreads      75
    ThreadLimit          64
    ThreadsPerChild      25
    MaxRequestWorkers     150
    MaxConnectionsPerChild   0
</IfModule>
prefork MPM

最後は、prefork MPMです。

prefork - Apache HTTP Server Version 2.4

ディレクティブ名 説明
StartServers 最初に起動するプロセス数
MaxRequestWorkers 同時に処理できる最大数(各プロセスごとのスレッド数の和の上限)
ServerLimit プロセス数の上限(MaxRequestWorkersよりも大きい値である必要がある)
MinSpareServers 待機プロセスの最少数
MaxSpareServers 待機プロセスの最大数

worker MPMやevent MPMと比べると、スレッドがない分だけシンプルになりましたね。待機分の設定も、スレッドではなくプロセス
(ディレクティブとしてはServer)になっています。

Ubuntu Linux 20.04 LTS/Apache 2.4.41での、prefork MPMのデフォルト設定はこちらです。

/etc/apache2/mods-available/mpm_prefork.conf

<IfModule mpm_prefork_module>
    StartServers             5
    MinSpareServers       5
    MaxSpareServers      10
    MaxRequestWorkers     150
    MaxConnectionsPerChild   0
</IfModule>

prefork MPMの場合、ServerLimitのデフォルト値は256です。

各MPMで、起動するプロセスやスレッド、受け付けられる接続数を実際に試して確認してみる

ここまでドキュメントを読みつつ各MPMを見ていきましたが、その設定と効果を実際に動かして確認してみたいと思います。

以下の内容で確認してみましょう。

  • 簡単なHTTPサーバーをApacheとは別に立て、Apacheからはmod_proxy_httpでプロキシする
    • このアプリケーションは、ApacheMaxRequestWorkers以上の接続数を受け入れられるものとする
    • かつ、とても処理が遅いものとする
  • ApacheのMPMを切り替えながら、Apacheに対して多数のアクセスを行う
    • プロキシ先が遅いので可能な接続数を使い切るはずなので、その時の接続数やプロセス数、スレッド数などを確認してみる
    • Apacheの各MPMの設定は、Ubuntu Linux 20.04 LTS/Apache 2.4.41でのデフォルト設定とする

簡単なHTTPサーバーは、Javaで作ります。Javaのバージョンはこちら。

$ java --version
openjdk 11.0.9.1 2020-11-04
OpenJDK Runtime Environment (build 11.0.9.1+1-Ubuntu-0ubuntu1.20.04)
OpenJDK 64-Bit Server VM (build 11.0.9.1+1-Ubuntu-0ubuntu1.20.04, mixed mode, sharing)

プログラムは、こういうものを用意しました。

SimpleHttpd.java

import java.io.IOException;
import java.io.OutputStream;
import java.net.InetSocketAddress;
import java.nio.charset.StandardCharsets;
import java.time.LocalDateTime;
import java.util.concurrent.Executors;
import java.util.concurrent.ExecutorService;
import java.util.concurrent.TimeUnit;

import com.sun.net.httpserver.HttpExchange;
import com.sun.net.httpserver.HttpHandler;
import com.sun.net.httpserver.HttpServer;

public class SimpleHttpd {
    public static void main(String... args) throws IOException {
        ExecutorService es = Executors.newFixedThreadPool(200);

        HttpServer server = HttpServer.create(new InetSocketAddress(8080), 0);
        server.setExecutor(es);
        server.createContext("/", new SimpleHttpHandler());
        server.start();

        System.out.println(LocalDateTime.now() + " server startup.");
    }

    static class SimpleHttpHandler implements HttpHandler {
        @Override
        public void handle(HttpExchange exchange) throws IOException {
            try {
                TimeUnit.SECONDS.sleep(60);
            } catch (InterruptedException e) {
                // ignore
            }

            byte[] message = "Hello World!!".getBytes(StandardCharsets.UTF_8);

            exchange.sendResponseHeaders(200, message.length);
            try (OutputStream os = exchange.getResponseBody()) {
                os.write(message);
            }
        }
    }
}

起動は、こんな感じで。

$ java SimpleHttpd.java 
2021-02-07T14:21:33.252448 server startup.

Hello World!!」と返すだけの簡単なサーバーですが、接続数は200、1リクエストごとに1分のスリープを行います。

このサーバーに対して、mod_proxy_httpでプロキシしましょう。

mod_proxy_httpを有効にして

$ sudo a2enmod proxy_http

Apacheをプロキシするように設定。

$ grep -vE '^\s*#' /etc/apache2/sites-enabled/000-default.conf
<VirtualHost *:80>

    ServerAdmin webmaster@localhost
    DocumentRoot /var/www/html


    ErrorLog ${APACHE_LOG_DIR}/error.log
    CustomLog ${APACHE_LOG_DIR}/access.log combined


    ProxyPass / http://localhost:8080
    ProxyPassReverse / http://localhost:8080
</VirtualHost>

確認。

$ time curl -i localhost
HTTP/1.1 200 OK
Date: Sun, 07 Feb 2021 05:30:04 GMT
Server: Apache/2.4.41 (Ubuntu)
Content-length: 13

Hello World!!
real    1m0.584s
user    0m0.013s
sys 0m0.025s

OKです。

アクセス数を出すためのツールとしては、Vegetaを使いました。

GitHub - tsenart/vegeta: HTTP load testing tool and library. It's over 9000!

インストール。

$ curl -sLO https://github.com/tsenart/vegeta/releases/download/v12.8.4/vegeta_12.8.4_linux_amd64.tar.gz
$ tar xf vegeta_12.8.4_linux_amd64.tar.gz

今回の環境での、バックログの上限も確認しておきます。

$ sysctl net.core.somaxconn
net.core.somaxconn = 4096

Apacheの設定としてはListenBackLogを使うようで、デフォルトで511のようです(今回は未設定)。

ListenBackLog Directive

worker MPM

まずは、worker MPMから確認しましょう。

event MPMからworker MPMへ切り替え、Apacheを再起動します。

$ sudo a2dismod mpm_event
$ sudo a2enmod mpm_worker
$ sudo systemctl restart apache2

worker MPMに切り替わったことを確認(Server MPM)。

$ apachectl -V
Server version: Apache/2.4.41 (Ubuntu)
Server built:   2020-08-12T19:46:17
Server's Module Magic Number: 20120211:88
Server loaded:  APR 1.6.5, APR-UTIL 1.6.1
Compiled using: APR 1.6.5, APR-UTIL 1.6.1
Architecture:   64-bit
Server MPM:     worker
  threaded:     yes (fixed thread count)
    forked:     yes (variable process count)
Server compiled with....
 -D APR_HAS_SENDFILE
 -D APR_HAS_MMAP
 -D APR_HAVE_IPV6 (IPv4-mapped addresses enabled)
 -D APR_USE_SYSVSEM_SERIALIZE
 -D APR_USE_PTHREAD_SERIALIZE
 -D SINGLE_LISTEN_UNSERIALIZED_ACCEPT
 -D APR_HAS_OTHER_CHILD
 -D AP_HAVE_RELIABLE_PIPED_LOGS
 -D DYNAMIC_MODULE_LIMIT=256
 -D HTTPD_ROOT="/etc/apache2"
 -D SUEXEC_BIN="/usr/lib/apache2/suexec"
 -D DEFAULT_PIDLOG="/var/run/apache2.pid"
 -D DEFAULT_SCOREBOARD="logs/apache_runtime_status"
 -D DEFAULT_ERRORLOG="logs/error_log"
 -D AP_TYPES_CONFIG_FILE="mime.types"
 -D SERVER_CONFIG_FILE="apache2.conf"

worker MPMの今回の設定はこちらです(再掲)。

<IfModule mpm_worker_module>
    StartServers             2
    MinSpareThreads      25
    MaxSpareThreads      75
    ThreadLimit          64
    ThreadsPerChild      25
    MaxRequestWorkers     150
    MaxConnectionsPerChild   0
</IfModule>

起動した時点でのプロセス数は、こうなっています。StartServersが2なので、子プロセスが2つある状態ですね。

$ ps aux | grep apache2 | grep -v grep
root         745  0.0  0.2   6752  4740 ?        Ss   20:14   0:00 /usr/sbin/apache2 -k start
www-data     746  0.0  0.2 1211648 4480 ?        Sl   20:14   0:00 /usr/sbin/apache2 -k start
www-data     747  0.0  0.2 1211648 4480 ?        Sl   20:14   0:00 /usr/sbin/apache2 -k start

スレッド数を見てみましょう。次のものは、PID単位でLWPをグルーピング、カウントしたものです。なので、プロセス自身の数も
含まれます。

$ ps aux -L | grep apache2 | grep -v grep | perl -awln -F'\s+' -e 'print "$F[0] $F[1]"' | sort | uniq -c
      1 root 1778
     27 www-data 1779
     27 www-data 1780

ですが、プロセス数の分を差し引いても26あります。ThreadsPerChildMinSpareThreadsも25なのですが、
ひとつ多いですね…。

まあ、この内訳には今回はこだわらず進みましょう。

Vegetaでワーカー数を300(今回のMaxRequestWorkersの倍)にして、待ち時間でタイムアウトしないように設定しつつアクセス。

$ echo 'GET http://localhost' | ./vegeta attack -duration 600s -max-workers 300 -timeout 120s

Vegetaでアクセスしている間の、Apacheの状態を見てみます。

子プロセスの数が6になりました。MaxRequestWorkers(150) / ThreadsPerChild(25)は6になるので、設定と合った結果に
なっていますね。

$ ps aux | grep apache2 | grep -v grep
root         745  0.0  0.2   6752  4740 ?        Ss   20:14   0:00 /usr/sbin/apache2 -k start
www-data     746  0.0  0.2 1213632 4480 ?        Sl   20:14   0:00 /usr/sbin/apache2 -k start
www-data     747  0.0  0.2 1213632 4480 ?        Sl   20:14   0:00 /usr/sbin/apache2 -k start
www-data    1646  0.2  0.2 1213632 4540 ?        Sl   20:27   0:00 /usr/sbin/apache2 -k start
www-data    1701  0.2  0.2 1213632 4540 ?        Sl   20:27   0:00 /usr/sbin/apache2 -k start
www-data    1702  0.2  0.2 1213632 4604 ?        Sl   20:27   0:00 /usr/sbin/apache2 -k start
www-data    1807  0.3  0.2 1213632 4540 ?        Sl   20:27   0:00 /usr/sbin/apache2 -k start

一方でスレッド数を見てみると、こうなっています。

$ ps aux -L | grep apache2 | grep -v grep | perl -awln -F'\s+' -e 'print "$F[0] $F[1]"' | sort | uniq -c
      1 root 745
     27 www-data 1646
     27 www-data 1701
     27 www-data 1702
     27 www-data 1807
     27 www-data 746
     27 www-data 747

Apacheのエラーログを見ると、MaxRequestWorkersに達したことが出力されています。

/var/log/apache2/error.log

[Sun Feb 07 20:27:11.011377 2021] [mpm_worker:error] [pid 745:tid 139631994985536] AH00286: server reached MaxRequestWorkers setting, consider raising the MaxRequestWorkers setting

プロセスあたりのスレッド数の+1分はちょっとわかっていませんが、概ね説明のとおりですね。

Apacheバックログも見てみましょう。アクセス元の300ワーカーのうち、150がRecv-Qに入っているのでこちらとも合ってそうです。

$ ss -tnl | grep -E 'State|:80 '
State    Recv-Q   Send-Q     Local Address:Port     Peer Address:Port  Process  
LISTEN   150      511                    *:80                  *:*
event MPM

次は、event MPMを確認しましょう。

event MPMに切り替えます。

$ sudo a2dismod mpm_worker
$ sudo a2enmod mpm_event
$ sudo systemctl restart apache2

確認。

$ apachectl -V
Server version: Apache/2.4.41 (Ubuntu)
Server built:   2020-08-12T19:46:17
Server's Module Magic Number: 20120211:88
Server loaded:  APR 1.6.5, APR-UTIL 1.6.1
Compiled using: APR 1.6.5, APR-UTIL 1.6.1
Architecture:   64-bit
Server MPM:     event
  threaded:     yes (fixed thread count)
    forked:     yes (variable process count)
Server compiled with....
 -D APR_HAS_SENDFILE
 -D APR_HAS_MMAP
 -D APR_HAVE_IPV6 (IPv4-mapped addresses enabled)
 -D APR_USE_SYSVSEM_SERIALIZE
 -D APR_USE_PTHREAD_SERIALIZE
 -D SINGLE_LISTEN_UNSERIALIZED_ACCEPT
 -D APR_HAS_OTHER_CHILD
 -D AP_HAVE_RELIABLE_PIPED_LOGS
 -D DYNAMIC_MODULE_LIMIT=256
 -D HTTPD_ROOT="/etc/apache2"
 -D SUEXEC_BIN="/usr/lib/apache2/suexec"
 -D DEFAULT_PIDLOG="/var/run/apache2.pid"
 -D DEFAULT_SCOREBOARD="logs/apache_runtime_status"
 -D DEFAULT_ERRORLOG="logs/error_log"
 -D AP_TYPES_CONFIG_FILE="mime.types"
 -D SERVER_CONFIG_FILE="apache2.conf"

event MPMの設定は、こちらです。

<IfModule mpm_event_module>
    StartServers             2
    MinSpareThreads      25
    MaxSpareThreads      75
    ThreadLimit          64
    ThreadsPerChild      25
    MaxRequestWorkers     150
    MaxConnectionsPerChild   0
</IfModule>

プロセスを確認。worker MPMの時と同じですね。

$ ps aux | grep apache2 | grep -v grep
root        2350  0.0  0.2   6772  4712 ?        Ss   21:02   0:00 /usr/sbin/apache2 -k start
www-data    2352  0.0  0.2 1211668 4436 ?        Sl   21:02   0:00 /usr/sbin/apache2 -k start
www-data    2353  0.0  0.2 1211668 4468 ?        Sl   21:02   0:00 /usr/sbin/apache2 -k start

プロセスごとのスレッド数に関しても同じです。

$ ps aux -L | grep apache2 | grep -v grep | perl -awln -F'\s+' -e 'print "$F[0] $F[1]"' | sort | uniq -c
      1 root 2350
     27 www-data 2352
     27 www-data 2353

では、負荷をかけてみます。

$ echo 'GET http://localhost' | ./vegeta attack -duration 600s -max-workers 300 -timeout 120s

この状態でプロセス数を見ると、worker MPMの時よりも多い9になっています(worker MPMは6)。

$ ps aux | grep apache2 | grep -v grep
root        2350  0.0  0.2   6772  4840 ?        Ss   21:02   0:00 /usr/sbin/apache2 -k start
www-data    2352  0.0  0.2 1213588 4436 ?        Sl   21:02   0:00 /usr/sbin/apache2 -k start
www-data    2353  0.0  0.2 1213660 4468 ?        Sl   21:02   0:00 /usr/sbin/apache2 -k start
www-data    2481  0.0  0.2 1213660 4472 ?        Sl   21:04   0:00 /usr/sbin/apache2 -k start
www-data    2534  0.0  0.2 1213340 4472 ?        Sl   21:04   0:00 /usr/sbin/apache2 -k start
www-data    2535  0.0  0.2 1211900 4472 ?        Sl   21:04   0:00 /usr/sbin/apache2 -k start
www-data    2614  0.0  0.2 1213660 4472 ?        Sl   21:04   0:00 /usr/sbin/apache2 -k start
www-data    2615  0.0  0.2 1213660 4472 ?        Sl   21:04   0:00 /usr/sbin/apache2 -k start
www-data    2616  0.0  0.2 1213020 4472 ?        Sl   21:04   0:00 /usr/sbin/apache2 -k start
www-data    2617  0.2  0.2 1213660 4472 ?        Sl   21:04   0:00 /usr/sbin/apache2 -k start

スレッド数。この計算だと、225スレッドあることになりますね。

$ ps aux -L | grep apache2 | grep -v grep | perl -awln -F'\s+' -e 'print "$F[0] $F[1]"' | sort | uniq -c
      1 root 2350
     27 www-data 2352
     27 www-data 2353
     27 www-data 2481
     27 www-data 2534
     27 www-data 2535
     27 www-data 2614
     27 www-data 2615
     27 www-data 2616
     27 www-data 2617

エラーログを見ると、MaxRequestWorkersに達したことが出力されています。

/var/log/apache2/error.log

[Sun Feb 07 21:04:43.278710 2021] [mpm_event:error] [pid 2350:tid 139858399816768] AH00484: server reached MaxRequestWorkers setting, consider raising the MaxRequestWorkers setting

バックログを見ると110なので、150だったworker MPMよりも40減っていますね。

$ ss -tnl | grep -E 'State|:80 '
State    Recv-Q   Send-Q     Local Address:Port     Peer Address:Port  Process  
LISTEN   110      511                    *:80                  *:*

つまり、worker MPMの設定と同じなのに40個の接続を受け入れていることになりますね。

さて、いろいろ計算がわからなくなりました。mod_statusで見ると、225のスレッドがビジーなワーカースレッドと認識されている
ようだったのですが、この225がどう計算したら出てくるのかがよくわかりません…。バックログMaxRequestWorkersの差である
40もそうなのですが…。

AsyncRequestWorkerFactor Directive

worker MPMより多めになるのはドキュメントからもわかるのですが…この確認は、今回はパスしましょう。

prefork MPM

最後はprefork MPMです。

prefork MPMに切り替えます。

$ sudo a2dismod mpm_event
$ sudo a2enmod mpm_prefork
$ sudo systemctl restart apache2

確認。

$ apachectl -V
Server version: Apache/2.4.41 (Ubuntu)
Server built:   2020-08-12T19:46:17
Server's Module Magic Number: 20120211:88
Server loaded:  APR 1.6.5, APR-UTIL 1.6.1
Compiled using: APR 1.6.5, APR-UTIL 1.6.1
Architecture:   64-bit
Server MPM:     prefork
  threaded:     no
    forked:     yes (variable process count)
Server compiled with....
 -D APR_HAS_SENDFILE
 -D APR_HAS_MMAP
 -D APR_HAVE_IPV6 (IPv4-mapped addresses enabled)
 -D APR_USE_SYSVSEM_SERIALIZE
 -D APR_USE_PTHREAD_SERIALIZE
 -D SINGLE_LISTEN_UNSERIALIZED_ACCEPT
 -D APR_HAS_OTHER_CHILD
 -D AP_HAVE_RELIABLE_PIPED_LOGS
 -D DYNAMIC_MODULE_LIMIT=256
 -D HTTPD_ROOT="/etc/apache2"
 -D SUEXEC_BIN="/usr/lib/apache2/suexec"
 -D DEFAULT_PIDLOG="/var/run/apache2.pid"
 -D DEFAULT_SCOREBOARD="logs/apache_runtime_status"
 -D DEFAULT_ERRORLOG="logs/error_log"
 -D AP_TYPES_CONFIG_FILE="mime.types"
 -D SERVER_CONFIG_FILE="apache2.conf"

prefork MPMの設定は、こうですね。

<IfModule mpm_prefork_module>
    StartServers             5
    MinSpareServers       5
    MaxSpareServers      10
    MaxRequestWorkers     150
    MaxConnectionsPerChild   0
</IfModule>

StartServersが5なので、起動時のプロセス数も5です、と。

$ ps aux | grep apache2 | grep -v grep
root        4674  0.0  0.2   6500  4452 ?        Ss   21:33   0:00 /usr/sbin/apache2 -k start
www-data    4675  0.0  0.1   6772  3824 ?        S    21:33   0:00 /usr/sbin/apache2 -k start
www-data    4676  0.0  0.1   6772  3824 ?        S    21:33   0:00 /usr/sbin/apache2 -k start
www-data    4677  0.0  0.1   6772  3824 ?        S    21:33   0:00 /usr/sbin/apache2 -k start
www-data    4678  0.0  0.1   6772  3824 ?        S    21:33   0:00 /usr/sbin/apache2 -k start
www-data    4679  0.0  0.1   6772  3824 ?        S    21:33   0:00 /usr/sbin/apache2 -k start

スレッドに関しては、確認する意味がありません。

$ ps aux -L | grep apache2 | grep -v grep | perl -awln -F'\s+' -e 'print "$F[0] $F[1]"' | sort | uniq -c
      1 root 4674
      1 www-data 4675
      1 www-data 4676
      1 www-data 4677
      1 www-data 4678
      1 www-data 4679

では、負荷をかけてみます。

$ echo 'GET http://localhost' | ./vegeta attack -duration 600s -max-workers 300 -timeout 120s

子プロセスが150まで増えました。

$ ps aux | grep apache2 | grep -v grep | wc -l
151

エラーログを確認すると、MaxRequestWorkersに達したことが出力されています。

/var/log/apache2/error.log

[Sun Feb 07 21:41:02.467235 2021] [mpm_prefork:error] [pid 5049] AH00161: server reached MaxRequestWorkers setting, consider raising the MaxRequestWorkers setting

バックログには、150ありますね。

$ ss -tnl | grep -E 'State|:80 '
State    Recv-Q   Send-Q     Local Address:Port     Peer Address:Port  Process  
LISTEN   150      511                    *:80                  *:*

だいたい、雰囲気はわかったのではないでしょうか。

まとめ

よくApacheのMPMの設定がわからなくなるので、この機会にちょっと確認してみました。

event MPMについてはちょっとよくわからないところがあるのですが、気が向いたらもうちょっと確認してみようかなと…。

いったん、雰囲気はわかったので良しとしましょう。