デバッグとプロファイリング

コードはあなたが期待した動きをするのではなく、あなたが書いた通りのことをするという黄金律がプログラミングにはあります。その差を埋めるのはときには大変困難な芸当になる場合もあります。この授業では、バグっていたりリソースを消費したりするようなコードに対処するための便利なテクニック、デバッグとプロファイリングについて扱います。

デバッグ

printf デバッグとロギング

「最も効果的なデバッグツールは依然として、思慮深く配置された print 文に伴った注意深い考察である」 — Brian Kernighan, Unix for Beginners

プログラムをデバッグする最初のアプローチは、何がこの問題に関係しているのかを理解するために必要な情報を得るまで、問題がありそうな場所に print 文を足すことを繰り返すというものです。

２番めのアプローチは、逐次 print 文を足す代わりにロギングを利用するというものです。ロギングは普通のprint文よりも、以下のようないくつかの理由により優れています。

ログを標準出力の代わりにファイルやソケット、リモートにあるサーバーに出力できます。
ロギングは深刻度（ INFO 、 DEBUG 、 WARN 、 ERROR など）をサポートしており、出力を適切にフィルターすることができます。
新しい問題が発生した際、何が悪かったのかを検出するために必要な問題がログにすでに含まれている可能性が結構あります。

これはログメッセージのサンプルコードです。

$ python logger.py
# printだけを利用した生の出力
$ python logger.py log
# 整形されたログの出力
$ python logger.py log ERROR
# ERROR以上のレベルのみを表示
$ python logger.py color
# 色付きの整形された出力

私のよくつかうログを読みやすくするためのコツのひとつとして、色を付けるというものがあります。これまでにおそらくすでにターミナルを読みやすくするため色が使われているのに気づいたことでしょう。これはどうすればできるのでしょうか？

ls や grep のようなプログラムは、 ANSI escape codes というシェルに出力の色を変えるように伝えるための特別な文字列を利用しています。例えば echo -e "\e[38;2;255;0;0mThis is red\e[0m" を実行すると、ターミナルが true color をサポートしている場合は This is red が赤色で出力されます。もしターミナルがそれをサポートしていなかった場合（例えば macOS の Terminal.app）、より普遍的にサポートされている１６色のエスケープコード、例えば echo -e "\e[31;1mThis is red\e[0m" を使うことができます。

以下のスクリプトは、どうやっていろいろなRGBカラーをターミナルに表示するかを表しています（ただし true color をサポートしている場合に限ります）。

#!/usr/bin/env bash
for R in $(seq 0 20 255); do
    for G in $(seq 0 20 255); do
        for B in $(seq 0 20 255); do
            printf "\e[38;2;${R};${G};${B}m█\e[0m";
        done
    done
done

第三者のログ

大きなソフトウェア・システムを構築し始めるにつれて、独立して動く他のプログラムとの依存関係の問題に直面することでしょう。ウェブサーバー、データベース、メッセージブローカーといったものはこのような依存関係のよくある例です。これらのシステムとやり取りをするときはクライアントサイドのエラーメッセージでは不十分なために、しばしばそれらのログを読む必要があります。

幸運なことに、多くのプログラムではシステムのどこかしらにログを書き込んでいます。 UNIX システムでは、プログラムがログを /var/log に書くのが一般的です。例えば、 NGINX ウェブサーバーはログを /var/log/nginx に置きます。より最近では様々なシステムが、すべてのログを集める場所である システムログ を使い始めるようになりました。（全てではないですが）ほとんどの Linux システムでは、有効化され実行されているサービスたちを始めとする多くのものを管理するシステムデーモン、 systemd を利用しています。 systemd はそのログを独自のフォーマットで /var/log/journal に置き、あなたは journalctl コマンドを使うことでメッセージを表示することができます。同様に、 macOS では依然として /var/log/system.log が存在しますが、徐々にシステムログを利用するツールの数は増えており、 log show で表示することができます。ほとんどの UNIX システムでは dmesg コマンドを利用してカーネルのログにアクセスすることもできます。

システムログにログを取るためには、シェルプログラム logger を使うことができます。これは logger を使う例と、システムログに作られたエントリーを確認する方法です。さらに、ほとんどのプログラミング言語ではシステムログにログを吐くためのバインディングが存在します。

logger "Hello Logs"
# On macOS
log show --last 1m | grep Hello
# On Linux
journalctl --since "1m ago" | grep Hello

「データの前処理」の授業で見たように、ログはとても冗長な場合があり、欲しい情報を得るためにはある程度の処理とフィルタリングをすることが必要です。もし journalctl や log show でフィルタリングしすぎているなと思ったら、フィルタリングの前に出力を捨てるフラグを使うことを考えましょう。また、 lnav のような、よりよい見た目やログファイル間の行き来をする機能を提供するようなツールがあります。

デバッガー

printfデバッギングが十分ではないときは、デバッガーを使うべきです。デバッガーは実行されているプログラムを操作するためのプログラムで、以下のような事ができます。

特定の行にきたときにプログラムの実行を止める
１命令ずつプログラムの実行を行う
プログラムがクラッシュした後に変数の値を調査する
ある条件を満たしたときにだけ実行を止める
などなど他にもより発展的な機能があります

多くのプログラミング言語は何らかの形でデバッガーを備えています。 Python では Python Debugger pdb です。

これは pdb がサポートするコマンドのいくつかの簡単な紹介です。

l(ist) - 今実行している行の周り11行か、前に表示していたコードを表示します。
s(tep) - 今の行を実行し、最初の停止できる場所で止まります。
n(ext) - 現在の関数の次の行まで、もしくは今の関数からリターンするまで実行を続けます。
b(reak) - 渡した引数に応じた breakpoint を設定します。
p(rint) - 現在のコンテキストで式を評価し、値を表示します。 pprint を代わりに利用して表示をする、 pp コマンドもあります。
r(eturn) - 現在の関数からリターンするまでプログラムを実行します。
q(uit) - デバッガーを終了します。

pdb をつかって、このバグがある Python のコードを直してみましょう（授業のビデオをみてください）。

def bubble_sort(arr):
    n = len(arr)
    for i in range(n):
        for j in range(n):
            if arr[j] > arr[j+1]:
                arr[j] = arr[j+1]
                arr[j+1] = arr[j]
    return arr

print(bubble_sort([4, 2, 1, 8, 7, 6]))

Python はインタープリター言語であり、コマンドやプログラムを実行できる pdb シェルがあります。 ipdb は IPython の REPL を用いた改良版の pdb で、pdb モジュールと同じインターフェースに加えて、タブキーでの予測変換が効いたり、シンタックスハイライティング、わかりやすいトレースバック、イントロスペクションなどが使えます。

より低いレベルのプログラミングでは gdb （に QoL を高める変更を加えた pwndbg や lldb ）を検討することでしょう。これらは C のような言語のデバッグに最適化されていますが、ほとんどどのようなプロセスでも調査でき、レジスタ、スタック、プログラムカウンタなどのマシンの状態を得ることができるでしょう。

特化したツール

たとえデバッグをしようとしている対象がブラックボックスのバイナリーだったとしても、あなたがデバッグをするのを手助けするツールがあります。 Linux カーネルしかできないようなことをする必要がある場合には、プログラムは System Calls を使います。プログラムが発行したシステムコールを追跡するいくつかのコマンドがあります。 Linuxシステムでは strace 、macOS や BSD では dtrace があります。 dtrace は独自の D 言語を利用する必要があるため使うのに癖がありますが、 strace と似たインターフェースを提供する dtruss というラッパーがあります（詳細はこちら）。

これは strace か dtruss をつかって ls を実行したときの stat システムコールを追跡した例です。より深く strace について知るためには、これを読むとよいでしょう。

# On Linux
sudo strace -e lstat ls -l > /dev/null

# On macOS
sudo dtruss -t lstat64_extended ls -l > /dev/null

状況によっては、あなたのプログラムの問題を理解するためにネットワークパケットを見る必要があるかもしれません。 tcpdump や Wireshark のようなツールはネットワークのパケットを分析するソフトウェアで、ネットワークのパケットを読んだり様々な基準でフィルターしたりすることができます。

ウェブ開発においては、ChromeやFirefoxの開発者ツールがとても便利です。たくさんの機能がありますが、たとえば以下のようなものが含まれています：

ソースコード - あらゆるサイトの HTML/CSS/JS のソースコードを調査する。
動的な HTML 、 CSS 、 JS の変更 - ウェブサイトの中身、スタイルや動作を変えてテストする（ウェブサイトのスクリーンショットが証拠として確実なものではないことがよく分かることでしょう）。
Javascript のシェル - JSのREPLでコマンドを実行する。
ネットワーク - リクエストのタイムラインを分析する。
ストレージ - クッキーやアプリケーションのストレージを見る。

静的解析

いくつかの問題に関しては、コードを実際に走らせる必要は全くありません。たとえば、じっくりコードを読むだけでもループ変数がすでにある変数や関数名を隠している（ shadowing ）ことや、プログラムが変数を定義する前に読み込んでいることに気づくかもしれません。これは、静的解析ツールが役に立つ分野です。静的解析のプログラムはソースコードを入力とし、その正しさを判断するためにコーディング規約に基づいて分析を行います。

以下の Python のコードはいくつかの誤りがあります。はじめに、ループ変数である foo はすでに定義されている関数 foo を隠しています。また、最後の行では bar ではなく baz と書いているので、プログラムは１分間かかる sleep を実行したあとにクラッシュしてしまいます。

import time

def foo():
    return 42

for foo in range(5):
    print(foo)
bar = 1
bar *= 0.2
time.sleep(60)
print(baz)

静的解析ツールはこういった問題を見つけ出すことができます。 pyflakes を走らせると両方のバグに関するエラーを確認することができます。また、 mypy を使うと型チェックをすることができます。この例で mypy は、 bar がはじめは int で初期化されているが後に float にキャストされている、という警告を出すでしょう。繰り返しになりますが、これらの問題はコードを走らせることなく検出することができます。

$ pyflakes foobar.py
foobar.py:6: redefinition of unused 'foo' from line 3
foobar.py:11: undefined name 'baz'

$ mypy foobar.py
foobar.py:6: error: Incompatible types in assignment (expression has type "int", variable has type "Callable[[], Any]")
foobar.py:9: error: Incompatible types in assignment (expression has type "float", variable has type "int")
foobar.py:11: error: Name 'baz' is not defined
Found 3 errors in 1 file (checked 1 source file)

シェルツールの講義では、シェルスクリプトのための似たようなツールである shellcheck を扱いました。

ほとんどのエディタやIDEでは、このようなツールの出力をエディタ内に表示し、警告やエラーの場所をハイライトする機能をサポートしています。これはよく code linting と呼ばれ、コードのスタイル違反や安全でない書き方といったエラーなどを表示するのにも使われます。

vim では、 ale や syntastic といったプラグインで lint を行うことができます。 Python では、 pylint や pep8 がスタイルの linter の代表的なものであり、 bandit　は一般的なセキュリティーに関する問題を見つけるためのツールです。他の言語では、多くの人が便利な静的解析ツールのリストを作成しています。たとえば Awesome Static Analysis (きっとあなたは Writing の章に興味があるでしょう) や、 linter でに関しては Awesome Linters があります。

スタイルの linting を行う補助的なツールとして、Python では black 、 Go では gofmt 、 Rust では rustfmt 、 JavaScript、HTML、CSS では prettier のようなコードフォーマッターがあります。これらのツールは、そのプログラミング言語の一般的なスタイルに合うようにあなたのコードを自動でフォーマットしてくれます。あなたはもしかすると自身のコードのスタイルに関して自分でコントロールできないことが気に入らないかもしれませんが、コードの書き方を標準化することは他の人があなたのコードを読むときに助けになりますし、あなたも他の人の（スタイルが標準化されている）コードを読みやすくなるでしょう。

プロファイリング

たとえあなたのコードが期待した動作をしているように振る舞っていたとしても、もしCPUやメモリをすべて使い果たしていたら、それは十分に良いとは言えないかもしれません。アルゴリズムの授業ではよく big O 記法を教えますが、あなたのプログラムの中のホットスポットの見つけかたは教えてくれません。早すぎる最適化はすべての悪の元凶 (premature optimization is the root of all evil) ですから、プロファイラーやモニタリングツールを学ばなければなりません。それのツールはプログラムのどの部分が最も時間やリソースを消費しているかを理解する手助けをしてくれるので、その部分を集中して最適化することができるようになります。

タイミング

デバッグのときと同じように、多くのシナリオではコード中の2点における時刻を表示するだけで十分だったりします。これは Python で time モジュールを使う例です。

import time, random
n = random.randint(1, 10) * 100

# 現在時刻の取得
start = time.time()

# なんらかの処理
print("Sleeping for {} ms".format(n))
time.sleep(n/1000)

# start と現在時刻の時間を計算
print(time.time() - start)

# 出力
# Sleeping for 500 ms
# 0.5713930130004883

しかし、実時間は、あなたのコンピューターが同時に他のプロセスを実行していたり、イベントが発生するのを待っていたりする場合に紛らわしい場合があります。ツールが Real、 User、 Sys 時間を区別するのはよくあることです。一般的に、 User + Sys はあなたのプロセスが実際に CPU 上で使った時間を表します（より詳細な説明はこちら）。

Real - プログラムの最初から最後までに経過した実時間であり、他のプロセスが消費した時間やブロックされていた時間（例： I/O やネットワークの待ち時間）も含む。
User - CPU 上でユーザーコードが走っていた時間
Sys - CPU 上でカーネルコードが走っていた時間

例えば、 HTTP リクエストを行うコマンドを time と前につけて実行してみましょう。ネットワークが遅い場合には、結果は以下のようなものになるでしょう。ここでは、リクエストが完了するまでに2sかかっていますが、プロセスは 15ms の CPU ユーザー時間と 12ms の CPU カーネル時間しか使っていません。

$ time curl https://missing.csail.mit.edu &> /dev/null
real    0m2.561s
user    0m0.015s
sys     0m0.012s

プロファイラー

CPU

人々が プロファイラー と言った際にはほとんどが CPU プロファイラー を指し、これは最も一般的なプロファイラーです。 CPU プロファイラーには大きく分けて トレーシング プロファイラーと サンプリング プロファイラーという2つのタイプがあります。トレーシングプロファイラーはプログラムの中で起こったすべての関数呼び出しを記録する一方で、サンプリングプロファイラーはプログラムを定期的に（一般的には1ミリ秒ごとに）調べ、プログラム中のスタックを記録します。これらのツールはその記録をつかって、あなたのプログラムがもっとも時間をつかったことに関する統計情報を表示します。これは、もしより詳細にこのトピックについて知りたい場合に良い導入のための記事となるでしょう。

ほとんどのプログラミング言語は、なんらかのコードを分析するために使えるコマンドライン上のプロファイラーを備えています。それらはよく一通りの機能を備えたIDEと合わせて利用されますが、この授業ではコマンドラインツールに焦点を当てていきましょう。

Python では、 cProfile モジュールを関数呼び出しの時間を測定するために利用できます。これは、原始的な grep を Python で実装した簡単な例です。

#!/usr/bin/env python

import sys, re

def grep(pattern, file):
    with open(file, 'r') as f:
        print(file)
        for i, line in enumerate(f.readlines()):
            pattern = re.compile(pattern)
            match = pattern.search(line)
            if match is not None:
                print("{}: {}".format(i, line), end="")

if __name__ == '__main__':
    times = int(sys.argv[1])
    pattern = sys.argv[2]
    for i in range(times):
        for file in sys.argv[3:]:
            grep(pattern, file)

このコードを以下のようなコマンドをつかってプロファイルすることができます。出力を分析することで、 IO がほとんどの時間を消費しており、正規表現をコンパイルするのにかなりの時間を使っていることもわかります。正規表現は一度だけコンパイルすればよいため、その部分を for 文から出すことができるでしょう。

$ python -m cProfile -s tottime grep.py 1000 '^(import|\s*def)[^,]*$' *.py

[omitted program output]

 ncalls  tottime  percall  cumtime  percall filename:lineno(function)
     8000    0.266    0.000    0.292    0.000 {built-in method io.open}
     8000    0.153    0.000    0.894    0.000 grep.py:5(grep)
    17000    0.101    0.000    0.101    0.000 {built-in method builtins.print}
     8000    0.100    0.000    0.129    0.000 {method 'readlines' of '_io._IOBase' objects}
    93000    0.097    0.000    0.111    0.000 re.py:286(_compile)
    93000    0.069    0.000    0.069    0.000 {method 'search' of '_sre.SRE_Pattern' objects}
    93000    0.030    0.000    0.141    0.000 re.py:231(compile)
    17000    0.019    0.000    0.029    0.000 codecs.py:318(decode)
        1    0.017    0.017    0.911    0.911 grep.py:3(<module>)

[omitted lines]

Python の cProfile プロファイラーの注意点として（多くのプロファイラーもそうですが）、関数呼び出しごとにかかる時間を表示しているということがあります。これは、特にサードパーティーのライブラリーをコード中で使っている場合に内部の関数呼び出しも結果に含まれてしまうため、あっという間に直感的ではなくなります。プロファイリングの情報を表示するのにより直感的な方法は、コードの行ごとにかかった時間を表示する方法であり、 ラインプロファイラー がこれをしてくれます。

例えば、この Python コードは授業のウェブサイトにリクエストを投げ、レスポンスを構文解析することでページ内のすべての URL を得ます。

#!/usr/bin/env python
import requests
from bs4 import BeautifulSoup

# これは、line_profilerにこの関数を
# 解析するよう伝えるデコレーターです。
@profile
def get_urls():
    response = requests.get('https://missing.csail.mit.edu')
    s = BeautifulSoup(response.content, 'lxml')
    urls = []
    for url in s.find_all('a'):
        urls.append(url['href'])

if __name__ == '__main__':
    get_urls()

もし Python の cProfile プロファイラーを使ったとしたら、2500行を超える、たとえソートしたとしてもどこで時間を使ったのか分かりづらいような出力を得るでしょう。 line_profiler を簡単に走らせれば、行ごとにかかった時間を表示することができます。

$ kernprof -l -v a.py
Wrote profile results to urls.py.lprof
Timer unit: 1e-06 s

Total time: 0.636188 s
File: a.py
Function: get_urls at line 5

Line #  Hits         Time  Per Hit   % Time  Line Contents
==============================================================
 5                                           @profile
 6                                           def get_urls():
 7         1     613909.0 613909.0     96.5      response = requests.get('https://missing.csail.mit.edu')
 8         1      21559.0  21559.0      3.4      s = BeautifulSoup(response.content, 'lxml')
 9         1          2.0      2.0      0.0      urls = []
10        25        685.0     27.4      0.1      for url in s.find_all('a'):
11        24         33.0      1.4      0.0          urls.append(url['href'])

メモリー

C や C++ のような言語では、メモリリークによってあなたのプログラムが必要のないメモリを決して解放しないということがあります。メモリーのデバッグを助けるため、メモリリークを検出する Valgrind のようなツールを使うことができます。

ガベージコレクションのある Python のような言語でも、オブジェクトへのポインターを持っている限りオブジェクトはガベージコレクションされないので、メモリープロファイラーを利用するのは役に立ちます。これは、プログラムの例とそれに対して memory-profiler を実行した結果です（line-profiler のようにデコレーターを使っていることに注意してください）。

@profile
def my_func():
    a = [1] * (10 ** 6)
    b = [2] * (2 * 10 ** 7)
    del b
    return a

if __name__ == '__main__':
    my_func()

$ python -m memory_profiler example.py
Line #    Mem usage  Increment   Line Contents
==============================================
     3                           @profile
     4      5.97 MB    0.00 MB   def my_func():
     5     13.61 MB    7.64 MB       a = [1] * (10 ** 6)
     6    166.20 MB  152.59 MB       b = [2] * (2 * 10 ** 7)
     7     13.61 MB -152.59 MB       del b
     8     13.61 MB    0.00 MB       return a

イベントプロファイリング

strace をデバッグのために使うような場合に、プロファイリング中にプログラムの一部分を無視し、ブラックボックスのように扱いたいかもしれません。 perf コマンドは CPU の差異を抽象化し時間やメモリを報告しませんが、代わりにあなたのプログラムに関係するシステムイベントを報告します。例えば、 perf を使うことで簡単にキャッシュの局所性が悪いこと、たくさんのページフォルトやロックなどがわかります。以下はコマンドの概要です。

perf list - perf で記録されたイベントの一覧を表示する
perf stat COMMAND ARG1 ARG2 - プロセスやコマンドに関係する異なるイベントの数を得る
perf record COMMAND ARG1 ARG2 - コマンドの実行を記録して、統計データを perf.data というファイルに保存する
perf report -　perf.data に記録されたデータを整形して表示する

可視化（ Visualization ）

実世界のプログラムからのプロファイラーの出力は、ソフトウェアプロジェクトの元来持つ複雑さにより、大量の情報を含むことでしょう。人類は視覚を重視する生物であり、大量の数字を読み取り意味を理解するのは大変苦手です。そのため、プロファイラーの出力を理解しやすい形に表示するツールはたくさんあります。

サンプリングプロファイラーからの CPU のプロファイル情報を表示するよくある方法のひとつに、 Flame Graph を使うというものがあります。これは、階層的な関数呼び出しを Y 軸に表示し、かかった時間を X 軸に比例するように表示します。これは対話型であり、プログラムの特定の箇所を拡大して、そのスタックトレースを得ることができます（以下の画像をクリックしてみてください）。

コールグラフ（ Call Graph ）や制御フローグラフ（ Control Flow Graph ）はプログラム中のサブルーチンの関係性を、関数をノード、関数呼び出しを有向エッジとして表示します。呼び出し回数や時間といったプロファイリングの情報とともに扱えば、コールグラフはプログラムの流れを解釈するのに大変役に立ちます。 Python では、 pycallgraph ライブラリを利用することでそれらを生成することができます。

Call Graph

リソースモニタリング

ときには、パフォーマンスを解析するにあたっての最初のステップとして、実際のリソースの消費量がどうなっているかを把握することでしょう。プログラムはしばしばリソースが足りないとき、たとえば十分なメモリがなかったりネットワークが遅い場合に遅くなります。 CPU 使用率やメモリ消費量、ネットワーク、ディスクの利用量といったいろいろなシステムのリソースを表示するための無数のツールが存在します。

一般的なモニタリング - おそらく最も有名なものは htop でしょう。これは改良版の top です。 htop はシステム上で実行されているプロセスの様々な統計を表示します。 htop は無数のオプションとショートカットキーがあり、有名なものだと <F6> でプロセスをソートし、 t で階層構造のツリーを表示し、 h でスレッドをトグルします。 glances も素晴らしい UI を持つ同じようなツールです。すべてのプロセスをまとめた測定結果を得るには dstat が気の利くツールであり、 I/O 、ネットワーク、 CPU 消費量、コンテキストスイッチといった様々なサブシステムのたくさんのリソースに関する情報をリアルタイムに計算することができます。
I/O 操作 - iotop は現在の I/O の使用量を表示することができ、プロセスが大量の I/O ディスク操作を行っていないか確認するのに便利です。
ディスク使用量 - df はパーティションごとの情報を表示し、 du はディスク（ disk ）の使用量（ usage ）を現在のディレクトリ内のファイルごとに表示します。これらのツールでは、 -h フラグを使うと人間（ human ）に読みやすい形式で表示することができます。 du のより対話的なバージョンとして、 ncdu というのもあり、これはフォルダーを移動しながら利用でき、ファイルやフォルダを削除することもできます。
メモリ使用量 - free はシステム内で使われているメモリーや利用できるメモリーの総量を表示します。メモリーは htop のようなツールにも表示されています。
使われているファイル - lsof はプロセスによって開かれたファイルについての情報を列挙します。これは、どのプロセスが特定のあるファイルを開いたのか確認するのに大変便利です。
ネットワーク接続と設定 - ss をつかうと、入ってきたり出ていったりするネットワークパケットやインターフェースに関する統計情報を監視することができます。 ss コマンドの一般的な利用法としては、マシンの特定のポートを使っているプロセスが何かを調べるというのがあります。ルーティングやネットワークデバイス、インターフェースを表示するには ip コマンドが使えます。 netstat や ifconfig は、これらのツールがあるため非推奨となりました。
ネットワーク使用量 - nethogs や iftop はネットワーク使用量を監視するための便利な対話的 CLI ツールです。

もしこれらのツールをテストしたいなら、 stress コマンドを使うことでマシンに人工的な負荷をかけることができます。

特化したツール

ときには、どのソフトウェアを利用するか決めるために、ブラックボックス化されたベンチマークを取ることが必要だったりします。 hyperfine のようなツールを使うと、コマンドラインプログラムのベンチマークをすぐに取ることができます。例えば、シェルツールとスクリプトの授業で find コマンドではなく fd コマンドを勧めました。 hyperfine をつかって、普段我々がよく実行するタスクについてこれらのツールを比べてみましょう。たとえば、以下のサンプルでは fd は find より私のマシン上で20倍高速でした。

$ hyperfine --warmup 3 'fd -e jpg' 'find . -iname "*.jpg"'
Benchmark #1: fd -e jpg
  Time (mean ± σ):      51.4 ms ±   2.9 ms    [User: 121.0 ms, System: 160.5 ms]
  Range (min … max):    44.2 ms …  60.1 ms    56 runs

Benchmark #2: find . -iname "*.jpg"
  Time (mean ± σ):      1.126 s ±  0.101 s    [User: 141.1 ms, System: 956.1 ms]
  Range (min … max):    0.975 s …  1.287 s    10 runs

Summary
  'fd -e jpg' ran
   21.89 ± 2.33 times faster than 'find . -iname "*.jpg"'

デバッグのためには、ブラウザーはウェブページの読み込みをプロファイリングするのに素晴らしいツールとなり、ローディング、レンダリング、スクリプティングなどのどこで時間を使ったのかを理解させてくれるでしょう。 Firefox や Chrome についての詳細は、これらのサイトを参照してください。

演習

デバッグ

Linux 上で journalctl 、もしくは macOS 上で log show をつかって最後にスーパーユーザーになって実行したコマンドを取得してください。もし何もなければ、害のない sudo ls のようなコマンドを実行して再度確認してみてください。
この pdb のハンズオンチュートリアルを行い、コマンドに慣れてください。より詳細なチュートリアルとしては、これを読んでみましょう。
shellcheck をインストールし、以下のスクリプトを確認してみてください。このコードの何が間違っているでしょうか？それを修正してみましょう。また、エディタに linter のプラグインをインストールし、自動的に警告が出るようにしてみましょう。
```
#!/bin/sh
## 例： いくつかの問題がある典型的なスクリプト
for f in $(ls *.m3u)
do
  grep -qi hq.*mp3 $f \
    && echo -e 'Playlist $f contains a HQ file in mp3 format'
done
```
（発展）reversible debugging について読み、 rr や RevPDB を使って簡単な例に取り組んでみてください。

プロファイリング

これはいくつかのソートアルゴリズムを実装したものです。 cProfile と line_profiler を使い、挿入ソートとクイックソートの実行時間を比べてみましょう。それぞれのアルゴリズムのボトルネックは何でしょうか。それから memory_profiler をつかってメモリー消費量を確認してみましょう。なぜ挿入ソートのほうが良いのでしょうか？それから、インプレースのバージョンのクイックソートを確認してみましょう。　チャレンジ： perf を使ってサイクルカウントとキャッシュヒット・ミスをそれぞれのアルゴリズムについて確認してみましょう。
これは、それぞれの値ごとの関数をつかってフィボナッチ数を求める（あきらかに複雑な） Python のコードです。
```
#!/usr/bin/env python
def fib0(): return 0

def fib1(): return 1

s = """def fib{}(): return fib{}() + fib{}()"""

if __name__ == '__main__':

    for n in range(2, 10):
        exec(s.format(n, n-1, n-2))
    # from functools import lru_cache
    # for n in range(10):
    #     exec("fib{} = lru_cache(1)(fib{})".format(n, n))
    print(eval("fib9()"))
```
このコードをファイルに保存し、実行できるようにしてください。また、事前にこれらをインストールしてください：pycallgraph 、 graphviz (もしすでに dot コマンドを実行できるなら、 GraphViz はすでにインストールされています)。コードをこのコマンドをつかって実行してください。 pycallgraph graphviz -- ./fib.py そして pycallgraph.png を確認してみましょう。何回 fib0 は呼ばれましたか？関数をメモ化することでこれより良くできます。コメントになっている部分のコメントを外してもう一度画像を生成してみてください。今回はそれぞれの fibN 関数は何回呼ばれているでしょうか？
リッスンしようとしているポートがすでに他のプロセスに取られていることはよくあります。そのプロセスの pid を見つける方法について学びましょう。最初に、 python -m http.server 4444 を実行し、 4444 ポートをリッスンしている最小のウェブサーバーを起動します。異なるターミナルで、 lsof | grep LISTEN を実行することですべてのリッスンしているプロセスやポートが表示されます。そのプロセスの pid を見つけ、 kill <PID> を実行することで終了させましょう。
プロセスのリソースを制限するのは便利なツールとなるかもしれません。 stress -c 3 を実行し、 htop で CPU 使用率を可視化してみましょう。さらに、 taskset --cpu-list 0,2 stress -c 3 を実行して可視化してみましょう。 stress は3つの CPU を使っているでしょうか？なぜ使っていないのでしょう？ man taskset を読んでみてください。チャレンジ：同じことを cgroups を使ってやってみてください。メモリー消費量を stress -m をつかって制限してみてください。
（発展） curl ipinfo.io というコマンドは HTTP リクエストを投げ、あなたのパブリック IP に関する情報を取得します。 Wireshark を開き、 curl が送受信したリクエストや応答のパケットを監視してみましょう。（ヒント： http フィルターを使うと HTTP のパケットのみを見ることができます。）

このページを編集する

Licensed under CC BY-NC-SA.