io.TeeReader を使って Teeコマンドを作る

f:id:dojineko:20170211215431j:plain

下記のエントリに触発されたのでかるーくやってみました。
ターゲットは tee コマンドです。

takatoshiono.hatenablog.com

teeコマンドって？

標準入力で受け取ったデータを標準出力しながら、
指定したファイルにも出力するようなコマンドです。

Linuxコマンド集 - 【 tee 】標準入力を標準出力とファイルに出力する：ITpro

他のコマンドの実行結果を tee にパイプして表示しつつログを取るというような使い方をしたりします。

io.TeeReaderって？

teeコマンドのように golang上で指定したReaderで読み取った内容を、
指定したWriterに渡しながら処理をすることのできるReaderです。

io - The Go Programming Language

サンプルプログラム

実際に使ってみないとなんともイメージが湧きにくいと思いますので
最低限 teeコマンドと同じ挙動をする gogotee というコマンドを作ってみます。

package main

import (
    "bufio"
    "fmt"
    "io"
    "log"
    "os"
)

func main() {
    if (len(os.Args) <= 1) || os.Args[1] == "" {
        log.Fatalln("filename is empty")
    }
    filename := os.Args[1]

    file, err := os.Create(filename)
    if err != nil {
        log.Fatalln("file open failed")
    }
    defer file.Close()

    tee := io.TeeReader(os.Stdin, file)

    s := bufio.NewScanner(tee)
    for s.Scan() {
        fmt.Println(s.Text())
    }
}

なんとたったこれだけでした。
最初 Github にパッケージとして上げようかと思ったのですがそれをするまでもないくらいに収まってしまいました…

Reader、Writerというキーワードが何度も出てくるので
あれ？どっちがうける方だっけかとなるかなーっという感じです。

流れとしては標準入力を受けながらファイルに出力するTeeReaderを用意して
bufioのScannerをつかって1行ずつデータをTeeReaderで処理しながら
画面に出力していくというような感じになっています。

ベンチマーク

早速なのでベンチマークを取ってみました 100万行出力するのにかかる時間を取ってみます。

# macOS の tee の場合
$ time (for i in `seq 1000000`; do echo $i; done | tee native.log) > /dev/null
( for i in `seq 1000000`; do; echo $i; done | tee native.log; ) > /dev/null  0.26s user 2.31s system 58% cpu 4.408 total
$ time (for i in `seq 1000000`; do echo $i; done | tee native.log) > /dev/null
( for i in `seq 1000000`; do; echo $i; done | tee native.log; ) > /dev/null  0.26s user 2.28s system 57% cpu 4.395 total
$ time (for i in `seq 1000000`; do echo $i; done | tee native.log) > /dev/null
( for i in `seq 1000000`; do; echo $i; done | tee native.log; ) > /dev/null  0.22s user 1.99s system 50% cpu 4.384 total

# go で作った tee モドキの場合
$ time (for i in `seq 1000000`; do echo $i; done | ./gogotee gogotee.log) > /dev/null
( for i in `seq 1000000`; do; echo $i; done | ./gogotee gogotee.log; ) >   0.88s user 2.13s system 73% cpu 4.124 total
$ time (for i in `seq 1000000`; do echo $i; done | ./gogotee gogotee.log) > /dev/null
( for i in `seq 1000000`; do; echo $i; done | ./gogotee gogotee.log; ) >   0.89s user 2.16s system 73% cpu 4.171 total
$ time (for i in `seq 1000000`; do echo $i; done | ./gogotee gogotee.log) > /dev/null
( for i in `seq 1000000`; do; echo $i; done | ./gogotee gogotee.log; ) >   0.88s user 2.10s system 71% cpu 4.187 total

実行時間はGoを使ったものが 0.2 秒ほど早いのですが、CPUを若干多めに使う様子。愚直に書いたコードなのでもっと遅くなるかと思いきやそうでもなかったのでビックリ。

io.TeeReaderをつかわずログだけ出力を変えてみる

io.TeeReaderはScanした結果をWriterに橋渡ししてReadできる機構ですが、ぶっちゃけそれを使わずとも意図した動作を作ることは可能です。

ということでログだけ出力を変えるパターンを用意してみます。
コードは下記のとおりです。ログだけ日時を追記した状態で出力するようにしてみました。

package main

import (
    "bufio"
    "fmt"
    "log"
    "os"
    "time"
)

func main() {
    if (len(os.Args) <= 1) || os.Args[1] == "" {
        log.Fatalln("filename is empty")
    }
    filename := os.Args[1]

    file, err := os.Create(filename)
    if err != nil {
        log.Fatalln("file open failed")
    }
    defer file.Close()

    s := bufio.NewScanner(os.Stdin)
    for s.Scan() {
        t := time.Now().Format("2006-01-02 15:04:05")
        // 画面に出力
        fmt.Println(s.Text())
        // ファイルに出力
        file.Write(([]byte)("[" + t + "] " + s.Text() + "\n"))
    }
}

ベンチも取ってみます

# macOS の tee
$ time (for i in `seq 1000000`; do echo $i; done | tee native.log) > /dev/null
( for i in `seq 1000000`; do; echo $i; done | tee native.log; ) > /dev/null  0.26s user 2.24s system 57% cpu 4.311 total
$ time (for i in `seq 1000000`; do echo $i; done | tee native.log) > /dev/null
( for i in `seq 1000000`; do; echo $i; done | tee native.log; ) > /dev/null  0.26s user 2.25s system 58% cpu 4.322 total
$ time (for i in `seq 1000000`; do echo $i; done | tee native.log) > /dev/null
( for i in `seq 1000000`; do; echo $i; done | tee native.log; ) > /dev/null  0.27s user 2.29s system 57% cpu 4.435 total

# gogotee ログだけ出力を変えたパターン
$ time (for i in `seq 1000000`; do echo $i; done | ./gogotee gogotee.log) > /dev/null
( for i in `seq 1000000`; do; echo $i; done | ./gogotee gogotee.log; ) >   1.31s user 2.04s system 79% cpu 4.183 total
$ time (for i in `seq 1000000`; do echo $i; done | ./gogotee gogotee.log) > /dev/null
( for i in `seq 1000000`; do; echo $i; done | ./gogotee gogotee.log; ) >   1.32s user 2.02s system 78% cpu 4.267 total
$ time (for i in `seq 1000000`; do echo $i; done | ./gogotee gogotee.log) > /dev/null
( for i in `seq 1000000`; do; echo $i; done | ./gogotee gogotee.log; ) >   1.33s user 2.02s system 79% cpu 4.247 total