🌊

プログレスバーをファイル出力する

2023/02/12に公開

Python

tqdm

tech

プログレスバー (Progress Bar)

下の様に処理の進捗状況をアニメーションっぽく表示する機能です:

コードは以下:

prog.py

from tqdm import tqdm
import time

for i in tqdm(range(10)):
    time.sleep(1)
print("tqdm finished")

参考: tqdmでプログレスバーを表示させる

やりたいこと

これをターミナルだけでなくログファイルにも出力したい。

問題点

以下の様に、単に標準出力をファイル出力すると:

python3 prog.py 2>&1 | tee out.log

以下の様に、プログレスバーが更新されるごとに新たな行が出力されてしまいます。

out.log

  0%|          | 0/10 [00:00<?, ?it/s]
 10%|█         | 1/10 [00:01<00:09,  1.00s/it]
 20%|██        | 2/10 [00:02<00:08,  1.00s/it]
 30%|███       | 3/10 [00:03<00:07,  1.00s/it]
 40%|████      | 4/10 [00:04<00:06,  1.00s/it]
 50%|█████     | 5/10 [00:05<00:05,  1.00s/it]
 60%|██████    | 6/10 [00:06<00:04,  1.00s/it]
 70%|███████   | 7/10 [00:07<00:03,  1.00s/it]
 80%|████████  | 8/10 [00:08<00:02,  1.00s/it]
 90%|█████████ | 9/10 [00:09<00:01,  1.00s/it]
100%|██████████| 10/10 [00:10<00:00,  1.00s/it]
100%|██████████| 10/10 [00:10<00:00,  1.00s/it]
tqdm finished

これは次の欠点が考えられます:

見返す価値のない情報が増えて見づらくなる
ファイルサイズが大きくなる

なので、ターミナルに表示されるものと同様なものをファイル出力する手段を検討しました。

解決結果

最終的なアウトプットは以下の様になります。

ソースコードの全体はこちらに置いてあります。

なぜ挙動が異なるのか

プログレスバーのつくりかた

改行せずに、キャリッジリターンのCR (\r) を先頭につけてターミナルに標準出力すると、前述したプログレスバーの動作をします。

この動作は以下の様にbashコマンドで確認できます:

なお、

echo -n: 改行なしで標準出力
$'\r', $'\n': キャリッジリターンの入力

キャリッジリターンのCR (\r) は行頭復帰を意味する制御コードで、ターミナルはこれを受け取ると出力位置を行頭に移動させます。これにより表示ログが上書きされていき、アニメーションのように動作しています。

ファイル出力時の動作の違い

bashのtee, >, >>やPythonのprint関数などでキャリッジリターンのCR (\r) をつけたままファイルに書き出すことはできます。しかし、これらの基本的なコマンドではファイルの末尾に文字列を追加していくことしかできないため、プログレスバーの過去の進捗率のログを上書きできません。

解決方法

bashのビルドインコマンドだけだとうまいやり方が見つからなかったのでGolangで実装しました。

大まかな処理内容は以下です:

出力のリダイレクト: プログレスバーの出力をGoにわたす
標準入力の逐次取得・ログ出力: Go で標準入力を受け取りログ出力し続ける
標準入力を行・CR単位で取得: 改行コード及びCRのどちらかが入力されると部分的に入力を受け取りファイル出力処理へまわす
古いプログレスバーの削除: CRが含まれる場合はファイル出力の前にログファイルの最終行を消去

以下、説明に必要な個所のみ解説とソースコードの抜粋をします。エラー処理などは割愛しています。動作可能なソースコードはこちらです。

出力のリダイレクト

以下の様に実行すると python からの標準出力を後続のアプリケーションの標準入力に逐次リダイレクトしてくれます。tqdm はプログレスバーを標準エラー出力 (stderr) に流すので 2>&1 をつけています:

python3 prog.py 2>&1 | hoge hoge

参考: Bashのリダイレクト(>と>&)とパイプ等についてのまとめ

標準入力の逐次取得・ログ出力

入力の取得はbufio.Scanner、ログ出力は bufio.Writer を使います。
bufio.Scanner.Split にわたす関数に応じて標準入力が逐次読み取られ、ログが逐次出力されます。

func main() {
	// Reader初期化
	sc := bufio.NewScanner(os.Stdin)
	// 後述 (ステップ2)
	sc.Split(ScanCRSeparatedLines)
	sc := bufio.NewScanner(os.Stdin)
	sc.Split(ScanCRSeparatedLines)

        // Writer初期化
	dstFile, err := os.OpenFile("out.log", os.O_APPEND|os.O_CREATE|os.O_RDWR, 0755)
	defer dstFile.Close()
	writer := bufio.NewWriter(dstFile)
	for sc.Scan() {
	        // 標準入力の逐次取得
		v := sc.Bytes()
		
		// 後述 (ステップ3)
		TrancateLastLine(dstFile)
		
		// ファイルに書き出し
		_, err := writer.Write(trimed_v)

		// ターミナルにも同じものを出力
		fmt.Print(string(v))

		writer.Flush()
	}
}

標準入力を行・CR単位で取得

bufio.Scanner.Splitにわたす関数 ScanCRSeparatedLines を定義します。デフォルトの bufio.ScanLines をベースに以下の箇所を変更・追加しています:

改行コードLFだけでなく行頭復帰CRでも入力を分割します。プログレスバーは処理が終わるまで改行コードを出力しないので、処理中はCRが入力されたら逐次取得するようにしています
後の処理で使いたいのでキャリッジリターンLF・CRをトリムせず残しています。

func ScanCRSeparatedLines(data []byte, atEOF bool) (advance int, token []byte, err error) {
	if atEOF && len(data) == 0 {
		return 0, nil, nil
	}
	if i := bytes.IndexByte(data, '\n'); i >= 0 {
		// We have a full newline-terminated line.
		return i + 1, data[0 : i+1], nil
	}
	if i := bytes.IndexByte(data, '\r'); i >= 0 {
		// We doesn't have a newline-terminated line but have a line for animation
		return len(data), data, nil
	}
	// If we're at EOF, we have a final, non-terminated line. Return it.
	if atEOF {
		return len(data), data, nil
	}
	// Request more data.
	return 0, nil, nil
}

これにより、1行(改行コードあり) or CRを少なくとも1つ含む1行(改行コードなし)が入力され次第その単位で値が (sc.Bytes() で) 読み取られ、処理が進みます。

古いプログレスバーの削除

上述したようにログファイルは、キャリッジリターンをあらわに書くと:

(プログレスバー動作時)

logging,\n
not related with progress bar ....\n
Processing...\n
\r 20%|██        | 2/10 [00:02<00:08,  1.00s/it]

(プログレスバーなし)

logging,\n
not related with progress bar ....\n
Processing...\n
100%|██████████| 10/10 [00:10<00:00,  1.00s/it]\n
Finished\n
Running next process...\n

のようになっているので、書き出したいログにCRが含まれる場合はファイル出力の前にログファイルの最終行 (正確には末端の改行コード \n 移行) を消去することでプログレスバーのアニメーションが再現されます。

os.File.ReadAt でバイト位置とバイト数を指定して読み出しが可能なので、ファイル終端から少しずつ読み出して、末端の改行コードの位置を探索します。また、os.File.Truncate でバイト位置を指定するとそれ以降の文字を削除できます。

const BUFSIZE = 4096

// Truncate a last line in fp. Reading file is operated.
func TruncateLastLine(fp *os.File) error {
	s, err := fp.Stat()

	start := int(s.Size() - BUFSIZE)
	sep := []byte("\n")
	buf := make([]byte, BUFSIZE)
	lastSep := -1
	if start < 0 {
		start = 0
		buf = make([]byte, s.Size())
	}
loop:
	for {
		_, err := fp.ReadAt(buf, int64(start))
                // 改行コードの探索
		lastSep = bytes.LastIndex(buf, sep)
		if lastSep >= 0 {
			// 末端の改行コード発見
			break loop
		} else {
			// not found.
			if start == 0 {
				// ファイルの先頭に到達したので終了
				break loop
			}

			// go to next loop
			start -= BUFSIZE
			buf = make([]byte, BUFSIZE)
			if start < 0 {
				start = 0
				buf = make([]byte, s.Size())
			}
		}
	}
	// truncate
	err = fp.Truncate(int64(start + lastSep + 1))
	return nil
}

まとめ

プログレスバーを逐次ファイル出力する方法の紹介と解説をしました。

今回はPython の tqdm を例にとって解説しましたが、tqdm や Python に限定した手法ではないので (要確認ですが) 広範囲で使えるかと思います。