Hatena::ブログ(Diary)

ablog このページをアンテナに追加 RSSフィード Twitter

2015-08-03

”私の環境で”大きなテキストファイルをawkで処理するときにcatで投げ込むと速い理由

大きなテキストファイルをawkで処理するときにcatで投げ込むと速い理由 - ablog を書きましたが、awk file > file より cat file|awk > file が速い環境は稀なようなので、私の環境でなぜ cat file|awk > file のほうが速いのか調べてみました。プロセススケジューラが関係しているようです。

f:id:yohei-a:20150802105256p:image:w640

↑はPerf + Flame Graphs で、awk file > file 実行時のコールスタックと所要時間を可視化したものです。


結論(たぶん)


分析結果

awk file > file

awk file > file では暗号化データを復号するカーネルスレッドawkプロセスプロセススケジューラがなぜか同じ CPUスケジューリングし、並列処理できていない。

  • awk file > file を実行する
$ time awk '$5 ~ /00$/ {print}' sample.txt > result1.txt
real	1m12.940s
user	0m59.059s
sys	0m1.477s
$ top -c 
# f を押して、j(Last used cpu (SMP))、l(CPU Time)、y(Sleeping in Function) を押して、return
top - 01:34:00 up  2:06,  8 users,  load average: 1.17, 0.90, 0.74
Tasks: 227 total,   3 running, 224 sleeping,   0 stopped,   0 zombie
Cpu(s): 20.6%us,  4.2%sy,  0.0%ni, 75.1%id,  0.0%wa,  0.0%hi,  0.1%si,  0.0%st
Mem:  16158544k total,  2895472k used, 13263072k free,     3176k buffers
Swap:  8085500k total,        0k used,  8085500k free,  2148524k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  P★CPU番号   TIME WCHAN     COMMAND
 9577 yazekats  20   0  103m  780  644 R 83.4  0.0   0:37.65 0   0:37 -         awk $5 ~ /00$/ {print} sample.txt ★カーネルスレッドと同じ CPU0 を使っている
 6230 root      20   0     0    0    0 S  8.6  0.0   0:09.30 0   0:09 worker_th [kworker/0:2] ★カーネルスレッドは CPU0 を使用
 9349 root      20   0     0    0    0 S  7.3  0.0   0:03.82 0   0:03 worker_th [kworker/0:1] ★カーネルスレッドは CPU0 を使用
 9303 yazekats  20   0 15204 1248  860 R  0.7  0.0   0:00.83 1   0:00 -         top -c
 6240 root      20   0     0    0    0 R  0.3  0.0   0:00.93 1   0:00 ?         [kworker/1:0]

top で表示されるCPU番号は正確には最後に使ったCPU番号です。


cat file|awk > file

cat file|awk > file では cat、awk、復号するカーネルスレッドが別々のCPUスケジューリングされ、並列処理できている。

  • cat file|awk > file を実行する。
$  time { cat sample.txt|awk '$5 ~ /00$/ {print}' > result2.txt; }
real	0m52.097s
user	0m50.920s
sys	0m2.846s
top - 01:45:59 up  2:18,  8 users,  load average: 1.37, 1.04, 0.83
Tasks: 228 total,   3 running, 225 sleeping,   0 stopped,   0 zombie
Cpu(s): 25.0%us,  6.2%sy,  0.0%ni, 68.7%id,  0.0%wa,  0.0%hi,  0.1%si,  0.0%st
Mem:  16158544k total,  2358376k used, 13800168k free,     5712k buffers
Swap:  8085500k total,        0k used,  8085500k free,  1604420k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  P★CPU番号   TIME WCHAN     COMMAND
 9721 yazekats  20   0  103m  780  644 R 99.7  0.0   0:23.06 3★   0:23 -         awk $5 ~ /00$/ {print} ★1CPUをほぼ使い切っている
 9672 root      20   0     0    0    0 S 20.3  0.0   0:19.08 0★   0:19 worker_th [kworker/0:1]
 9720 yazekats  20   0 98.6m  484  416 S  4.0  0.0   0:00.91 2★   0:00 pipe_wait★ cat sample.txt ★cat はこの瞬間はパイプへの書込み待ちでスリープ

検証

  • taskset コマンドで awk file > file 実行時に使うCPU番号を明示的に指定すると、awk と復号するカーネルスレッドが別のCPUを使って並列処理され、速くなりました。
$ time taskset -c 3 awk '$5 ~ /00$/ {print}' sample.txt > result1.txt
real	0m54.180s ★ cat file|awk > file に近い実行時間になっています
user	0m51.277s
sys	0m1.151s
Tasks: 226 total,   2 running, 224 sleeping,   0 stopped,   0 zombie
Cpu(s): 24.0%us,  5.5%sy,  0.0%ni, 70.5%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Mem:  16158544k total,  3458788k used, 12699756k free,     6656k buffers
Swap:  8085500k total,        0k used,  8085500k free,  2698136k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  P★CPU番号   TIME WCHAN     COMMAND
 9783 yazekats  20   0  103m  780  644 R 97.6★  0.0   0:43.60 3★   0:43 -         awk $5 ~ /00$/ {print} sample.txt
 9784 root      20   0     0    0    0 S 18.6  0.0   0:05.79 0★   0:05 worker_th [kworker/0:2]
 4431 yazekats  20   0 15196 1236  856 S  0.7  0.0   0:24.78 1   0:24 poll_sche top -c

補足

  • 検証の前には都度ページキャッシュを解放しています。
# echo 3 > /proc/sys/vm/drop_caches
  • ベースライン
$ time { awk '$5 ~ /00$/ {print}' sample.txt > result1.txt; }
real	1m9.755s
user	0m56.078s
sys	0m1.593s
$ time { cat sample.txt | awk '$5 ~ /00$/ {print}' > result2.txt; }
real	0m59.299s
user	0m56.994s
sys	0m4.005s
  • "> file" しなくても実行時間はほぼ同じため、write はボトルネックになっていない。
$ time { awk '$5 ~ /00$/ {print}' sample.txt > /dev/null; }
real	1m11.339s
user	0m57.730s
sys	0m1.304s
$ time { awk '$5 ~ /00$/ {}' sample.txt; }
real	1m8.525s
user	0m55.022s
sys	0m1.420s
$ time { cat sample.txt|awk '$5 ~ /00$/ {print}' > /dev/null; }
real	0m55.854s
user	0m54.418s
sys	0m3.293s
$  time { cat sample.txt|awk '$5 ~ /00$/ {}'; }
real	0m58.242s
user	0m56.425s
sys	0m3.540s
  • awk に posix_fadivse(SEQUENTIAL) を入れても速くならない。
$ pwd
/usr/src/gnu/gawk-3.1.7
$ diff io.c io.c.org 
27d26
< #include "fadvise.h"
1679d1677
< 	posix_fadvise(openfd, 0, 0, POSIX_FADV_SEQUENTIAL);
$ ./configure
$ make
$ strace /usr/src/gnu/gawk-3.1.7/gawk '{print}' sample.txt 2>&1|grep -C2 fadvise
open("sample.txt", O_RDONLY) = 3
fstat(3, {st_mode=S_IFREG|0664, st_size=2800000000, ...}) = 0
fadvise64(3, 0, 0, POSIX_FADV_SEQUENTIAL) = 0
ioctl(3, SNDCTL_TMR_TIMEBASE or TCGETS, 0x7fffa7cb3930) = -1 ENOTTY (Inappropriate ioctl for device)
fstat(3, {st_mode=S_IFREG|0664, st_size=2800000000, ...}) = 0
$ time { /usr/src/gnu/gawk-3.1.7/gawk '$5 ~ /00$/ {print}' sample.txt > result1.txt; }
real 1m9.574s
user 0m56.812s
sys 0m1.408s

参考


関連

2015-07-28

大きなテキストファイルをawkで処理するときにcatで投げ込むと速い理由

はじめに

awk file より cat file|awk のほうが速いという以下のブログエントリが興味深いので調べてみました。

ちなみに cat file|awk が速くなる環境は稀で、巷では awk file のほうが速い環境のほうが多いようで、どちらが速いかは環境依存です。

[root@localhost sample]# cat command1
awk '$5 ~ /((26|27|28|29|30)\/Jun|(01|02|03)\/Jul)/{ print }' sample.txt > result1.txt
(中略)
[root@localhost sample]# time sh command1

real    0m53.926s
user    0m0.926s
sys 0m33.158s
[root@localhost sample]# cat command2
cat sample.txt | awk '$5 ~ /((26|27|28|29|30)\/Jun|(01|02|03)\/Jul)/{ print }' > result2.txt
(中略)
[root@localhost sample]# time sh command2

real    0m30.789s
user    0m2.644s
sys 0m22.277s

結論

条件によるとは思うけど、catしたほうがはやいっぽい。

大きなテキストファイルをawkで処理するときにcatで投げ込むのと、ファイル読み込みするのどっちが速いか比較 - カメニッキ

仮説


結論(仮)


検証結果

仮説を立てた上で、"Don’t guess, measure!(推測するな、計測せよ!)”ということで、検証してみました。

テストデータ作成
  • テストデータを作成する(5000万行で約2.7GB)
$ perl -MTime::Piece -e 'printf(qq/%08d %08d %08d %08d %s\n/,$_,2..4,$t=localtime->datetime) for 1..50000000' > sample.txt
$ ls -lh sample.txt 
-rw-rw-r-- 1 yazekats yazekats 2.7G Jul 28 14:40 sample.txt
$ wc -l sample.txt 
50000000 sample.txt
$ head -3 sample.txt 
00000001 00000002 00000003 00000004 2015-07-28T14:23:18
00000002 00000002 00000003 00000004 2015-07-28T14:23:18
00000003 00000002 00000003 00000004 2015-07-28T14:23:18

実行時間測定
# echo 3 > /proc/sys/vm/drop_caches
  • awk file の場合
$ time { awk '$5 ~ /00$/ {print}' sample.txt > result1.txt; }
real	1m9.755s
user	0m56.078s
sys	0m1.593s
# echo 3 > /proc/sys/vm/drop_caches
  • cat file|awk の場合
$ time { cat sample.txt | awk '$5 ~ /00$/ {print}' > result2.txt; }
real	0m59.299s
user	0m56.994s
sys	0m4.005s

と、awk file より cat file|awk のほうが速い。cat file|awk は実行時間をCPU時間が上回っているため、cat のプロセスawkプロセスが並列実行されていると想定できる。

実行時間(59.299s) < CPU時間(60.999) = user(56.994s) + sys(4.005s)

なぜこうなるかというとパイプはバッファを持っているからだと思います。

$  strace -Ttt cat sample.txt |while read LINE
> do
> sleep 10
> echo $LINE
> done
00:36:53.673164 execve("/bin/cat", ["cat", "sample.txt"], [/* 89 vars */]) = 0 <0.000332>
...
00:36:53.677511 read(3, "00000001 00000002 00000003 00000"..., 32768) = 32768 <0.000049>
00:36:53.677627 write(1, "00000001 00000002 00000003 00000"..., 32768) = 32768 <0.000622>
00:36:53.678330 read(3, " 00000002 00000003 00000004 2015"..., 32768) = 32768 <0.000039>
00:36:53.678439 write(1, " 00000002 00000003 00000004 2015"..., 32768) = 32768 <0.000031>
00:36:53.678536 read(3, "2 00000003 00000004 2015-07-28T1"..., 32768) = 32768 <0.000028>
# ↑まだ read していないのに 96KB まで read して、64KB くらい write している
00:36:53.678629 write(1, "2 00000003 00000004 2015-07-28T1"..., 3276800000001 00000002 00000003 00000004 2015-07-28T14:23:18
00000002 00000002 00000003 00000004 2015-07-28T14:23:18
00000003 00000002 00000003 00000004 2015-07-28T14:23:18
00000004 00000002 00000003 00000004 2015-07-28T14:23:18

書籍で調べてみると、パイプを使うとプロセス空間とパイプ用バッファの間でデータがやり取りされ、バッファ(2.6.11以降は16個。4KB * 16個 = 64KB)が一杯になるまで書込みできると書かれています。後述しますが、cat のI/Oサイズは 32KB なので、awk で read されなくても、cat はパイプ用バッファに2回 write することができます。

Linuxカーネル2.6解読室

Linuxカーネル2.6解読室

P.327

18.3.4 パイプのリード・ライト

パイプに対してリード・ライトを行うと、パイプ用バッファプロセス空間の間でデータがやり取りされます。

(中略)

2.6.10 までは、バッファは1つでしたが、2.6.11 以降複数(16個)になっています。(中略)ライトでは書くスペースが全くない場合、書くスペースができるまでスリープします。

Pipe capacity

A pipe has a limited capacity. If the pipe is full, then a write(2) will block or fail, depending on whether the O_NONBLOCK flag is set (see below). Different implementations have different limits for the pipe capacity. Applications should not rely on a particular capacity: an application should be designed so that a reading process consumes data as soon as it is available, so that a writing process does not remain blocked.

In Linux versions before 2.6.11, the capacity of a pipe was the same as the system page size (e.g., 4096 bytes on i386). Since Linux 2.6.11, the pipe capacity is 65536 bytes. Since Linux 2.6.35, the default pipe capacity is 65536 bytes, but the capacity can be queried and set using the fcntl(2) F_GETPIPE_SZ and F_SETPIPE_SZ operations. See fcntl(2) for more information.

PIPE_BUF

POSIX.1-2001 says that write(2)s of less than PIPE_BUF bytes must be atomic: the output data is written to the pipe as a contiguous sequence. Writes of more than PIPE_BUF bytes may be nonatomic: the kernel may interleave the data with data written by other processes. POSIX.1-2001 requires PIPE_BUF to be at least 512 bytes. (On Linux, PIPE_BUF is 4096 bytes.) The precise semantics depend on whether the file descriptor is nonblocking (O_NONBLOCK), whether there are multiple writers to the pipe, and on n, the number of bytes to be written:

pipe(7) - Linux manual page

今回の検証に使った Kernel 2.6.39 でも16個でした。

#define PIPE_DEF_BUFFERS	16

従って、awk file|awk すると速くなります。

# echo 3 > /proc/sys/vm/drop_caches
$ time { awk '{print}' sample.txt | awk '$5 ~ /00$/ {print}' > result3.txt; }
real	0m57.671s
user	1m5.399s
sys	0m2.495s

また、パイプ用バッファの恩恵を享受できないような大きなI/Oサイズにすると直列化して遅くなり、I/Oサイズを小さくすると並列処理できる時間が長くなり、速くなります。

# echo 3 > /proc/sys/vm/drop_caches
$ time { dd if=sample.txt bs=32k| awk '$5 ~ /00$/ {print}' > result4.txt; }
85449+1 records in
85449+1 records out
2800000000 bytes (2.8 GB) copied, 59.405 s, 47.1 MB/s

real	0m59.549s
user	0m56.090s
sys	0m4.124s
# echo 3 > /proc/sys/vm/drop_caches
$ time { dd if=sample.txt bs=1024k| awk '$5 ~ /00$/ {print}' > result4.txt; }
2670+1 records in
2670+1 records out
2800000000 bytes (2.8 GB) copied, 74.642 s, 37.5 MB/s

real	1m14.762s <-- I/Oサイズを1MBにすると遅くなる
user	0m58.936s
sys	0m4.493s
# echo 3 > /proc/sys/vm/drop_caches
$ time { dd if=sample.txt bs=4k| awk '$5 ~ /00$/ {print}' > result4.txt; }
683593+1 records in
683593+1 records out
2800000000 bytes (2.8 GB) copied, 52.7871 s, 53.0 MB/s

real	0m52.900s <--I/Oサイズを小さくして、並列処理効率を上げると速くなる
user	0m51.536s
sys	0m3.348s
$ strace dd if=sample.txt bs=1024k|while read LINE
> do
> sleep 10
> echo $LINE
> done
execve("/bin/dd", ["dd", "if=sample.txt", "bs=1024k"], [/* 65 vars */]) = 0
(中略)
read(0, "00000001 00000002 00000003 00000"..., 1048576) = 1048576
write(1, "00000001 00000002 00000003 00000"..., 1048576^C <unfinished ...> <--I/Oサイズが1MBの場合、処理が直列化

補足

プロセスCPU使用率I/O量の分析

@hasegaw さんの prociostat.pl と visualize_prociostat.Rで分析してみると、awk file(約45MB/s) より cat file|awk(55MB/s) のほうがI/Oスループットが高いことがわかります。*1

awk file だと I/O と ON CPU での処理が完全に直列になりますが、cat file|awk だとパイプ用バッファの恩恵を享受して awk が ON CPU で処理中にも cat がささやかながらもI/O処理を並列実行してくれるからだと思います。

    • awk file (delta_read_bytes は約 45MB/s)

f:id:yohei-a:20150728234144p:image:w640

    • cat file| (delta_read_bytes は約 55MB/s)

f:id:yohei-a:20150728234142p:image:w640

f:id:yohei-a:20150728234141p:image:w640

上記グラフを作成した手順は以下の通りです。

$ perl prociostat.pl -C -p 7000-9999 # prociostat.pl を実行後、計測したい処理(awk や cat|awk)を実行 
^C # 計測したい処理が終わったら Ctrl + C で終了
$ ls *.txt|xargs -n1 Rscript visualize_prociostat.R # R でグラフ化

I/Oサイズ

I/Oサイズは関係ありませんでした。cat のI/Oサイズが 32KB、awkI/Oサイズが 4KB だったので、awkI/Oサイズを 32KB に大きくしても実行時間はほぼ同じです。

  • awkI/O サイズは 4KB
$ strace awk '$5 ~ /00$/ {print}' sample.txt > result1.txt
...
read(3, "00299009 00000002 00000003 00000"..., 4096) = 4096 <- I/Oサイズが 4KB
read(3, " 00000002 00000003 00000004 2015"..., 4096) = 4096
  • cat のI/Oサイズは 32 KB
$ strace cat sample.txt | awk '$5 ~ /00$/ {print}' > result2.txt
...
read(3, "004 2015-07-28T14:23:25\n00362790"..., 32768) = 32768 <- I/Oサイズが 32KB
write(1, "004 2015-07-28T14:23:25\n00362790"..., 32768) = 32768
  • AWKBUFSIZE 環境変数awkI/Oサイズを大きくしても、実行時間はほぼ変わらない。
$ export AWKBUFSIZE=32768
$ strace awk '$5 ~ /00$/ {print}' sample.txt > result1.txt
...
read(3, "00688129 00000002 00000003 00000"..., 32768) = 32768 <- I/Oサイズが 32KB になっていることを確認
read(3, " 00000002 00000003 00000004 2015"..., 32768) = 32768
...
$ time { awk '$5 ~ /00$/ {print}' sample.txt > result1.txt; } 
real	1m10.359s <-- I/Oサイズを32KBにしても実行時間はほぼ同じ
user	0m56.891s
sys	0m1.491s

awk のソース

今回使った gawk 3.1.7 のソースを見ると、AWKBUFSIZE 環境変数を設定すると read(2) システムコール発行時の I/O サイズを調整できることがわかります。

/* iop_alloc --- allocate an IOBUF structure for an open fd */

static IOBUF *
iop_alloc(int fd, const char *name, IOBUF *iop)
{
	struct stat sbuf;
	struct open_hook *oh;
	int iop_malloced = FALSE;

	if (iop == NULL) {
		emalloc(iop, IOBUF *, sizeof(IOBUF), "iop_alloc");
		iop_malloced = TRUE;
	}
	memset(iop, '\0', sizeof(IOBUF));
	iop->flag = 0;
	iop->fd = fd;
	iop->name = name;

	/* walk through open hooks, stop at first one that responds */
	for (oh = open_hooks; oh != NULL; oh = oh->next) {
		if ((iop->opaque = (*oh->open_func)(iop)) != NULL)
			break;
	}

	if (iop->fd == INTERNAL_HANDLE)
		return iop;

	if (iop->fd == INVALID_HANDLE) {
		if (iop_malloced)
			free(iop);
		return NULL;
	}
	if (isatty(iop->fd))
		iop->flag |= IOP_IS_TTY;
	iop->readsize = iop->size = optimal_bufsize(iop->fd, & sbuf);
	iop->sbuf = sbuf;
	if (do_lint && S_ISREG(sbuf.st_mode) && sbuf.st_size == 0)
		lintwarn(_("data file `%s' is empty"), name);
	errno = 0;
	iop->count = iop->scanoff = 0;
	emalloc(iop->buf, char *, iop->size += 2, "iop_alloc");
	iop->off = iop->buf;
	iop->dataend = NULL;
	iop->end = iop->buf + iop->size;
	iop->flag |= IOP_AT_START;
	return iop;
}

...

/* <getarecord>=                                                            */
/* get_a_record --- read a record from IOP into out, return length of EOF, set RT */

static int
get_a_record(char **out,        /* pointer to pointer to data */
        IOBUF *iop,             /* input IOP */
        int *errcode)           /* pointer to error variable */
{
        struct recmatch recm;
        SCANSTATE state;
        RECVALUE ret;
        int retval;
        NODE *rtval = NULL;
	static RECVALUE (*lastmatchrec)P((IOBUF *iop, struct recmatch *recm, SCANSTATE *state)) = NULL;

        if (at_eof(iop) && no_data_left(iop))
                return EOF;

	if (iop->get_record != NULL)
		return (*iop->get_record)(out, iop, errcode);

        /* <fill initial buffer>=                                                   */
        if (has_no_data(iop) || no_data_left(iop)) {
		if (is_internal(iop)) {
			iop->flag |= IOP_AT_EOF;
			return EOF;
		}
                iop->count = read(iop->fd, iop->buf, iop->readsize);
                if (iop->count == 0) {
                        iop->flag |= IOP_AT_EOF;
                        return EOF;
                } else if (iop->count == -1) {
                        if (! do_traditional && errcode != NULL) {
                                *errcode = errno;
                                iop->flag |= IOP_AT_EOF;
                                return EOF;
                        } else
                                fatal(_("error reading input file `%s': %s"),
                                        iop->name, strerror(errno));
                } else {
                        iop->dataend = iop->buf + iop->count;
                        iop->off = iop->buf;
                }
        }
/* optimal_bufsize --- determine optimal buffer size */

/*
 * Enhance this for debugging purposes, as follows:
 *
 * Always stat the file, stat buffer is used by higher-level code.
 *
 * if (AWKBUFSIZE == "exact")
 * 	return the file size
 * else if (AWKBUFSIZE == a number)
 * 	always return that number
 * else
 * 	if the size is < default_blocksize
 * 		return the size
 *	else
 *		return default_blocksize
 *	end if
 * endif
 *
 * Hair comes in an effort to only deal with AWKBUFSIZE
 * once, the first time this routine is called, instead of
 * every time.  Performance, dontyaknow.
 */

size_t
optimal_bufsize(fd, stb)
int fd;
struct stat *stb;
{
	char *val;
	static size_t env_val = 0;
	static short first = TRUE;
	static short exact = FALSE;

	/* force all members to zero in case OS doesn't use all of them. */
	memset(stb, '\0', sizeof(struct stat));

	/* always stat, in case stb is used by higher level code. */
	if (fstat(fd, stb) == -1)
		fatal("can't stat fd %d (%s)", fd, strerror(errno));

	if (first) {
		first = FALSE;

		if ((val = getenv("AWKBUFSIZE")) != NULL) {
			if (strcmp(val, "exact") == 0)
				exact = TRUE;
			else if (ISDIGIT(*val)) {
				for (; *val && ISDIGIT(*val); val++)
					env_val = (env_val * 10) + *val - '0';

				return env_val;
			}
		}
	} else if (! exact && env_val > 0)
		return env_val;
	/* else
	  	fall through */

	/*
	 * System V.n, n < 4, doesn't have the file system block size in the
	 * stat structure. So we have to make some sort of reasonable
	 * guess. We use stdio's BUFSIZ, since that is what it was
	 * meant for in the first place.
	 */
#ifdef HAVE_ST_BLKSIZE
#define DEFBLKSIZE	(stb->st_blksize > 0 ? stb->st_blksize : BUFSIZ)
#else
#define DEFBLKSIZE	BUFSIZ
#endif

	if (S_ISREG(stb->st_mode)		/* regular file */
	    && 0 < stb->st_size			/* non-zero size */
	    && (stb->st_size < DEFBLKSIZE	/* small file */
		|| exact))			/* or debugging */
		return stb->st_size;		/* use file size */

	return DEFBLKSIZE;
}

補足

$ ls -hs result*
45M result1.txt  45M result2.txt
$ md5sum result1.txt 
5c54faf7dc1e0cf93cbf474a921f05d8  result1.txt
$ md5sum result2.txt 
5c54faf7dc1e0cf93cbf474a921f05d8  result2.txt

検証環境


参考


追記(2015/07/30):

「catはposix_fadivse(SEQUENTIAL)してるからOSの先読み量が倍に」が正しいんじゃないの?/id:nippondanji そうですね。ただ「マルチプロセスだと速い」は理由の説明として不十分。正解は多分→https://gist.github.com/kazuho/074e2c82a2c09b9255c5

「catはposix_fadivse(SEQUENTIAL)してるからOSの先読み量が倍に」が正しいんじゃないの?/id:nippondanji そうですね。ただ「マルチプロセスだと速い」は理由の説明として不十分。正解は多分→https://gist.github.com/kazuho/074e2c82a2c09b9255c5 - kazuhooku のコメント

「catはposix_fadivse(SEQUENTIAL)してるからOSの先読み量が倍に」は違いました。

本検証に使った cat は"posix_fadivse(SEQUENTIAL)" が入る前のものでした。

$ cat --version|head -1                                                     
cat (GNU coreutils) 8.4
$ strace cat sample.txt 2>&1|grep -C2 fadvise                               
$ /usr/src/gnu/coreutils-8.24/src/cat --version|head -1                     
cat (GNU coreutils) 8.24
$ strace /usr/src/gnu/coreutils-8.24/src/cat sample.txt 2>&1|grep -C2 fadvise
open("sample.txt", O_RDONLY)            = 3
fstat(3, {st_mode=S_IFREG|0664, st_size=2800000000, ...}) = 0
fadvise64(3, 0, 0, POSIX_FADV_SEQUENTIAL) = 0
mmap(NULL, 139264, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fa10fc25000
read(3, "00000001 00000002 00000003 00000"..., 131072) = 131072

8.4 より 8.24 のほうが少し速くなっていますね。

# echo 3 > /proc/sys/vm/drop_caches
$ time cat sample.txt > /dev/null

real	0m10.597s
user	0m0.014s
sys	0m1.188s
# echo 3 > /proc/sys/vm/drop_caches
$ time /usr/src/gnu/coreutils-8.24/src/cat sample.txt > /dev/null

real	0m10.374s
user	0m0.003s
sys	0m1.028s

2010年7月に cat に posix_fadivse(SEQUENTIAL) が入っていますが、検証に使っていたのはこの変更が入る前のものでした。古っ。。。

provide POSIX_FADV_SEQUENTIAL hint to appropriate utils
author	P&#225;draig Brady <P@draigBrady.com>	
Tue, 20 Jul 2010 17:51:01 +0000 (18:51 +0100)
committer	P&#225;draig Brady <P@draigBrady.com>	
Thu, 22 Jul 2010 00:04:47 +0000 (01:04 +0100)
Following on from commit dae35bac, 01-03-2010,
"sort: inform the system about our input access pattern"
apply the same hint to all appropriate utils.
This currently gives around a 5% speedup for reading
large files from fast flash devices on GNU/Linux.

* src/base64.c: Call fadvise (..., FADVISE_SEQUENTIAL);
* src/cat.c: Likewise.
* src/cksum.c: Likewise.
* src/comm.c: Likewise.
* src/cut.c: Likewise.
* src/expand.c: Likewise.
* src/fmt.c: Likewise.
* src/fold.c: Likewise.
* src/join.c: Likewise.
* src/md5sum.c: Likewise.
* src/nl.c: Likewise.
* src/paste.c: Likewise.
* src/pr.c: Likewise.
* src/ptx.c: Likewise.
* src/shuf.c: Likewise.
* src/sum.c: Likewise.
* src/tee.c: Likewise.
* src/tr.c: Likewise.
* src/tsort.c: Likewise.
* src/unexpand.c: Likewise.
* src/uniq.c: Likewise.
* src/wc.c: Likewise, unless we don't actually read().

...

diff --git a/src/cat.c b/src/cat.c
index c4a2a9e..47b5053 100644 (file)
--- a/src/cat.c
+++ b/src/cat.c
@@ -34,6 +34,7 @@
 
 #include "system.h"
 #include "error.h"
+#include "fadvise.h"
 #include "full-write.h"
 #include "quote.h"
 #include "safe-read.h"
@@ -700,6 +701,8 @@ main (int argc, char **argv)
         }
       insize = io_blksize (stat_buf);
 
+      fdadvise (input_desc, 0, 0, FADVISE_SEQUENTIAL);
+
       /* Compare the device and i-node numbers of this input file with
          the corresponding values of the (output file associated with)
          stdout, and skip this input file if they coincide.  Input

追記(2015/08/01):

  • cat file|awk の場合
$ time { cat sample.txt | awk '$5 ~ /00$/ {print}' > result2.txt; }
real	0m59.299s
user	0m56.994s
sys	0m4.005s

と、awk file より cat file|awk のほうが速い。cat file|awk は実行時間をCPU時間が上回っているため、cat のプロセスawkプロセスが並列実行されていると想定できる。

実行時間(59.299s) < CPU時間(60.999) = user(56.994s) + sys(4.005s)

cat file|awk では実行時間 < CPU時間となっていますが、cat が I/O wait していないとは限りません。実行時間は単純に終了時間 - 開始時間で算出しますが、CPU時間はプロセスCPU時間を getrusage システムコールで取得します。catのプロセスawkプロセスが並列実行されている期間があるため、実行時間 < CPU時間となっています。例えば、CPUバウンドな2プロセスがほぼ完全に並列実行されると、実行時間 * 2 ≒ CPU時間 となったりします。

cat と awk を単体で実行すると以下のように I/O wait していることがわかります。

strace と ltrace の出力結果を見ると、getrusageシステムコールCPU時間やgettimeofdayで実行時間を取得している様子がわかります。

$ time cat sample.txt > /dev/null
real	0m10.612s
user	0m0.011s
sys	0m1.187s
$ time awk '{print}' sample.txt > /dev/null
real	0m18.219s
user	0m10.866s
sys	0m1.370s

以下の絵のようなイメージになります。

f:id:yohei-a:20150801143823p:image:w640

$ strace -Ttt -s 1024 -o strace.log -p $$ &
# echo 3 > /proc/sys/vm/drop_caches
$ time { cat sample.txt | awk '$5 ~ /00$/ {print}' > result2.txt; }
real	0m58.899s
user	0m56.770s
sys	0m4.044s
$ kill %1
$ ltrace -Ttt -s 1024 -o ltrace.log -p $$ &
# echo 3 > /proc/sys/vm/drop_caches
$ time { cat sample.txt | awk '$5 ~ /00$/ {print}' > result2.txt; }
real	0m57.311s
user	0m55.533s
sys	0m3.795s
$ kill %1

以下は strace と ltrace の出力結果です。

$ grep -B2 'getrusage'  strace.log 
12:05:03.907771 close(3)                = 0 <0.000037>
12:05:03.907951 rt_sigaction(SIGINT, {0x4529f0, [], SA_RESTORER, 0x3c9b2326a0}, {0x4529f0, [], SA_RESTORER, 0x3c9b2326a0}, 8) = 0 <0.000020>
12:05:03.908207 getrusage(RUSAGE_SELF, {ru_utime={0, 163975}, ru_stime={0, 55991}, ...}) = 0 <0.000023>12:05:03.908386 getrusage(RUSAGE_CHILDREN, {ru_utime={131, 756969}, ru_stime={132, 210900}, ...}) = 0 <0.000019> ★
--
12:05:58.560637 wait4(-1, 0x7fffd6cd1a5c, WNOHANG|WSTOPPED|WCONTINUED, NULL) = 0 <0.000018>
12:05:58.560804 rt_sigreturn(0x11)      = 0 <0.000029>
12:05:58.560939 getrusage(RUSAGE_SELF, {ru_utime={0, 164974}, ru_stime={0, 55991}, ...}) = 0 <0.000008>12:05:58.561005 getrusage(RUSAGE_CHILDREN, {ru_utime={185, 247838}, ru_stime={135, 103461}, ...}) = 0 <0.000006> ★
$ grep -B2 'getrusage'  ltrace.log 
18302 14:04:20.802949 malloc(32)                                                                       = 0x16b0c70 <0.000160>
18302 14:04:20.803260 gettimeofday(0x7fff392c73a0, 0x7fff392c73e0)                                     = 0 <0.000150>18302 14:04:20.803559 getrusage(0, 0x7fff392c7300, 803425, 0, 0x16b0670)                               = 0 <0.000198>18302 14:04:20.803918 getrusage(0xffffffff, 0x7fff392c71e0, 803425, -1, 0x16b0670)                     = 0 <0.000187> ★
--
18302 14:05:18.113908 <... sigprocmask resumed> )                                                      = 0 <0.000551>
18302 14:05:18.113974 gettimeofday(0x7fff392c7390, 0x7fff392c73e0)                                     = 0 <0.000081>18302 14:05:18.114124 getrusage(0, 0x7fff392c7270, 114063, 0, 0xffffffff)                              = 0 <0.000097>18302 14:05:18.114349 getrusage(0xffffffff, 0x7fff392c7150, 114063, -1, 0xffffffff)                    = 0 <0.000223>

strace で gettimeofday システムコールが出てこないのは VDSO (Virtual Dynamic Shared Object) によりユーザーモードで実行されているためです(参考:gettimeofday(2) は VDSO によりユーザー空間で実行される - ablog)。

bash の time のコードは以下のあたりと思われる。

clock_t
times(tms)
	struct tms *tms;
{
	clock_t rv;
	static long clk_tck = -1;

#if defined (HAVE_GETRUSAGE)
	struct timeval tv;
	struct rusage ru;

	if (clk_tck == -1)
		clk_tck = get_clk_tck();

	if (getrusage(RUSAGE_SELF, &ru) < 0) ★
		return ((clock_t)-1);
	tms->tms_utime = CONVTCK(ru.ru_utime); ★
	tms->tms_stime = CONVTCK(ru.ru_stime); ★

	if (getrusage(RUSAGE_CHILDREN, &ru) < 0) ★
		return ((clock_t)-1);
	tms->tms_cutime = CONVTCK(ru.ru_utime); ★
	tms->tms_cstime = CONVTCK(ru.ru_stime); ★

	if (gettimeofday(&tv, (struct timezone *) 0) < 0) ★
		return ((clock_t)-1);
	rv = (clock_t)(CONVTCK(tv));

*1Perlスクリプトで /proc/<pid>/stat の delta_utime、delta_stime、delta_delayacct_blkio_ticks、/proc/<pid>/io の read_bytes、write_bytes を1秒間隔でCSVに出力して、Rでグラフにしています。

2015-07-16

SQL*Plus で spool やリダイレクトするとスペースがタブになるのが嫌な場合は set tab off

質問されたので、書いときます。

次は SQL*Plus の SET システム変数 TAB。

SET TAB { ON | OFF } - SETシステム変数の一覧

sqlplus の出力をファイルに spool した後に眺めてみると、画面上では空白だと思っていたものが実は TAB 文字でした残念!という事が嫌なときには OFF に設定します。私は固定長が好きなので大抵 OFF にしています

Oracle Databaseを扱う上で知っておきたい変数10選 - Keep It Simple, Stupid

2015-07-11

Perlワンライナー集

障害対応でのログ解析、ソースコードの調査といったテキスト処理で使った Perl ワンライナー集です。

マルチライナーやいけてないのもありますw



Perl ワンライナーの好きなところ

  • PerlOracle Database (10g以降) に同梱されているので、Windows プラットフォームでも使える*1
  • awksedgrep正規表現の書き方などをそれぞれ覚えれない。awksedgrep でできることはだいたい Perl でできるので、Perl に絞ると覚えることを減らせる*2
  • 最小限の労力で最大限の仕事ができる。ちょっとしたプログラムを書くような処理でも Perl ワンライナーを使うとたった1行で済むことがあります*3

Perlワンライナー

一部、Perl 以外に bash、find、xargs なども含んでいます。

perl -wple ...       # 行モード(デフォルト)
perl -00 -wle ...    # 段落モード(1つ以上の空行をレコードセパレータと認識する)
perl -0777 -wle ...  # ファイルモード(ファイル全体を1レコードとして認識する)
  • カスタムフィールドセパレータを使う(改行コードをフィールドセパレータとする)
perl -00 -F'\n' -lane 'print $F[1] if($F[0] =~ /neo/)' hoge.txt
  • テキストファイルの特定の行だけ表示する
perl -lne 'print if $.<2' file  # 1行目だけ表示する
perl -pe 'exit if $. > 10' file # 10行目まで表示する
perl -ne 'print if 2.. 5' file  # 2行目から5行目まで表示する
  • CSV の列数をカウントする
perl -F, -lane 'printf("%s:%d\n",$ARGV,$#F);$.>0 and close ARGV' *.csv
  • CSV の任意の列のみ抽出する(1列目、3列目、11列目以外を抽出する)
perl -F, -lane 'print join(",",@F[1,3..9,11..$#F])' *.csv
  • ファイル中の空行を削除する
perl -i.org -ne '/^\s*$/ or print' test.sql
  • ダブルクオートをシングルクオートに置換する
perl -ple 's/\"/\'/g' hoge.csv
  • 「ORA-」メッセージをエラー番号別に集計する
perl -nle 'BEGIN{%h=();}/(ORA-[0-9]+)/ and $h{$1}++;END{map{print qq/$_:$h{$_}/} keys %h;}' alert_orcl.log
perl -wnle 'BEGIN{%h=();}/([a-zA-Z]*Exception)/ and $h{$1}++;END{map{print "$_:$h{$_}"} sort keys %h;}' *.log
  • リスナーログから接続元ホスト毎に接続回数を算出する
perl -nle 'if(/(\d{2}-\w{3}-\d{4} \d{2}:\d{2}:\d{2}).*CONNECT_DATA.*HOST=([\w\-\.]+).*HOST=([\w\-\.]+)/i){$h->{qq/$2,$3/}->{count}++;$h->{qq/$2,$3/}->{date}=$1};END{map{print qq/$_,$h->{$_}->{count},$h->{$_}->{date}/} keys %$h}' listener.log
  • 再帰的にファイル名に接頭辞をつける
perl -MFile::Find -e 'find sub{rename($_,"prefix_$_") if -f}, @ARGV' .
  • テキストファイル中の最長行の文字数を求める
perl -nle '$a=length if($a<length);END{print $a}' orcl_ora_879.trc 
perl -MList::Util=max -lne 'push(@a,length);END{print max(@a)}' orcl_ora_879.trc 
perl -0777 -MEncode::Guess -wne '$e=guess_encoding($_,qw/euc-jp shiftjis 7bit-jis/);print "$ARGV:".$e->name."\n" if(ref($e))' **/*
 ||<
-任意のディレクトリ配下にどのような拡張子のファイルがどれだけあるか集計する
>|perl|
perl -MFile::Find -MFile::Basename -e 'find sub{$h{(fileparse($_,qw{\.[^\.]+$}))[2]}++ if -f},@ARGV;END{map{print "$_:$h{$_}\n"}keys %h}' .
  • 2つ以上の空白文字は1つにするがシングルクオートで囲まれたリテラルは無視する
perl -pe 's/\G((\x27[^\x27]*\x27[^\x27]*?)*[^\x27]*?)[ ]+/$1 /g' foo.c
perl -i.org -00 -pe 's/^(.*)\n(.*)\n+$/$1 $2\n/' aaa.txt
  • 1ファイル中に「DECODE」と「DISTINCTまたはUNIQUE」を含みかつ「ORDER BY」を含まないファイルをリストアップする
find . -type f -print0|xargs -0 perl -0777 -nle '/decode/i and /distinct|unique/i and !/order\s*by/i and print qq/$ARGV:$./;eof and close ARGV'
find . -type f -name '*.sh' -print0|xargs -0 perl -i.org -0777 -pe 's/(\s*#![\w\s\/]+\/bash)/$1\nexport LANG=C\n/'
  • ASCIIコードを文字に変換する
perl -e 'map{print chr($_)} @ARGV' 112 101 114 108  # ASCIIコードが10進数の場合
perl -e 'map{print chr(hex($_))} @ARGV' 70 65 72 6C # ASCIIコードが16進数の場合
  • メモリを大量消費する
perl -e 'while(1){$i++;$h{$i}=$i}' 
perl -e 'while(1) {}'
for i in {1..4}
do
perl -e 'while(1){}' &
done
  • iostat の出力結果を特定の列でソートするこの例では、デバイスsdk だけに絞って、(11列目) でソートしています。
perl -lane '/^sdk/ and push(@tmp,[@F]);END{map{print join(qq/ /,@{$_})}sort{$a-[11]<=>$b->[11]}@tmp}' iostat.log
perl -F, -lane '/global cache blocks lost/ and printf(qq/%s,%s\n/,$F[0],$F[2]-$tmp) and $tmp=$F[2]' sysstat.log
perl -F, -lane 'printf(qq/%s,%s,%s\n/,$F[1],$F[0],$F[2]-$h{$F[1]})if(exists($h{$F[1]}));$h{$F[1]}=$F[2]' sysstat.log
  • vmstat の出力結果から時間帯毎のCPU使用率を算出する
perl -lane '$.>2 and @t=split(q/:/,$F[1]) and $h->{$t[0]}->{sum}+=$F[21]+$F[22] and $h->{$t[0]}->{cnt}++;END{map{printf(qq/%02d\t%.1f\n/,$_,$h->{$_}->{sum}/$h->{$_}->{cnt})}sort keys %$h}' vmstat.log
  • top の行頭に時刻を追加
perl -ne '/^top - (\d\d:\d\d:\d\d)/ and $t=$1;print qq/$t $_/' top.log > top_time.log
  • 2行にまたがっている iostat のログを1行にする
perl -pe '/sssn[0-9]+s:/ and chop' iostat.txt > iostat_tmp.txt
perl -pe 's/(sssn[0-9]+s:[\/\w]+)iostat\s[0-9\/]{10}\s[0-9:]{8}/$1/' iostat_tmp.txt > iostat_mod.txt
perl -i -MEncode -pe 'Encode::from_to($_,"utf8","shiftjis");' *.txt"
  • ファイル名一括置換
perl -0777 -ne '$o=$ARGV;$ARGV=~s/\s/-/g;rename($o,$ARGV);' *.jpg
  • 16進数から10進数に変換
perl -e 'map{print hex($_)} @ARGV' 4a98
  • 10進数から16進数に変換
perl -e 'printf qq/%X/, 19096'
perl -MTime::HiRes -e 'while(1){for(1..10000){};Time::HiRes::sleep(0.0001)}'
  • strace をグラフ化するために加工する
perl -lane '$F[2]=~s/^([a-z]+).*/$1/; $h->{$F[1]}->{$F[2]}++;END{map{$t=$_ and print $t;map{print qq/$t\t$_\t$h->{$t}->{$_}/} keys %{$h->{$_}}} keys %$h}'' strace.log
  • top を時系列・PID別にグラフ化するために加工する
grep -hA 20 '^top -' top.logperl -lane '/top - ([\d:]+)/ and $t=$1;$F[0]=~/\d+/ and printf (qq/%s %s%s\n/,$t,$_,lc(sprintf(q/%X/,$F[0])))'
  • 素のASHCSVなどデリミタ区切りに変換する
perl -lane '/^-+/ and map {$l=length($_);$l++;print qq/a$l/} @F' ash.lst
a11a11a76a2a11a16a11a11a11a14a2a17a11a25a14a21a65a20a17a31a31a12a9a22a26a16a20a15a14a19a11a65a11a11a11a65a11a65a11a65a11a65a14a11a8a12a12a17a25a17a2a13a14a15a13a16a65a18a17a17a11a2a2a2a2a2a2a2a2a2a2a2a2a2a2a2a13a49a65a65a65a65a11a65a17a22a14a18a17a11a23a24a20a21a28a14a21a1001
perl -nle '@s=unpack(q/a11a11a76a2a11a16a11a11a11a14a2a17a11a25a14a21a65a20a17a31a31a12a9a22a26a16a20a15a14a19a11a65a11a11a11a65a11a65a11a65a11a65a14a11a8a12a12a17a25a17a2a13a14a15a13a16a65a18a17a17a11a2a2a2a2a2a2a2a2a2a2a2a2a2a2a2a13a49a65a65a65a65a11a65a17a22a14a18a17a11a23a24a20a21a28a14a21a1001/, $_);@t=map{$_=~s/^ *(.*?) *$/$1/;$_} @s;print join(q/|/, @t)' ash.lst > ash_mod.txt 

参考


関連

*1Oracle Database使い向け

*2:記憶力がよくない人向け

*3Perlに限りませんが

2015-07-08

funcgraph で Linux カーネル内のボトルネックをミクロに追跡する

perf + Flame Graphs で Linux カーネル内のボトルネックを特定する - ablog

Linux カーネル内のボトルネックマクロに分析する方法を紹介しましたが*1

システムコールインターフェースカーネルのブロックレイヤーの中間(ファイルシステムレイヤーなど)で詰まっていると考えられます*3

f:id:yohei-a:20150708100823p:image:w360

このようなケースで、1回のシステムコール発行の所要時間の内訳*4をミクロに追跡するには Brendan Gregg の funcgraph が便利です*5

f:id:yohei-a:20150708084950p:image:w640


実行結果

# ./funcgraph -Htp 4511 vfs_write
Tracing "vfs_write" for PID 4511... Ctrl-C to end.
# tracer: function_graph
#
#     TIME        CPU  DURATION                  FUNCTION CALLS
#      |          |     |   |                     |   |   |   |
  935.579600 |   3)               |  vfs_write() {
  935.579602 |   3)               |    rw_verify_area() {
  935.579602 |   3)               |      security_file_permission() {
  935.579602 |   3)   0.085 us    |        cap_file_permission();
  935.579603 |   3)   0.810 us    |      }
  935.579603 |   3)   1.367 us    |    }
  935.579604 |   3)               |    do_sync_write() {
  935.579604 |   3)               |      pipe_write() {
  935.579604 |   3)               |        mutex_lock() {
  935.579604 |   3)   0.044 us    |          _cond_resched();
  935.579605 |   3)   0.434 us    |        }
  935.579605 |   3)   0.159 us    |        pipe_iov_copy_from_user();
  935.579606 |   3)   0.097 us    |        mutex_unlock();
  935.579606 |   3)               |        __wake_up_sync_key() {
  935.579606 |   3)   0.096 us    |          _raw_spin_lock_irqsave();
  935.579607 |   3)   0.062 us    |          __wake_up_common();
  935.579607 |   3)   0.070 us    |          _raw_spin_unlock_irqrestore();
  935.579608 |   3)   1.441 us    |        }
  935.579608 |   3)   0.133 us    |        kill_fasync();
  935.579609 |   3)               |        file_update_time() {
  935.579609 |   3)               |          current_fs_time() {
  935.579609 |   3)   0.046 us    |            current_kernel_time();
  935.579610 |   3)   0.048 us    |            timespec_trunc();
  935.579610 |   3)   0.881 us    |          }
  935.579610 |   3)               |          mnt_want_write_file() {
  935.579611 |   3)   0.257 us    |            mnt_want_write();
  935.579611 |   3)   0.764 us    |          }
  935.579611 |   3)   0.225 us    |          __mark_inode_dirty();
  935.579612 |   3)   0.044 us    |          mnt_drop_write();
  935.579612 |   3)   3.495 us    |        }
  935.579613 |   3)   8.489 us    |      }
  935.579613 |   3)   9.035 us    |    }
  935.579613 |   3)   0.055 us    |    __fsnotify_parent();
  935.579613 |   3)               |    fsnotify() {
  935.579614 |   3)   0.164 us    |      __srcu_read_lock();
  935.579614 |   3)   0.044 us    |      __srcu_read_unlock();
  935.579615 |   3)   1.253 us    |    }
  935.579615 |   3) + 13.624 us   |  }

手順

# curl -L -O https://raw.githubusercontent.com/brendangregg/perf-tools/master/kernel/funcgraph
# chmod u+x funcgraph
# mount -t debugfs debugfs /sys/kernel/debug
# ps -ef|grep [c]hrome
# ./funcgraph -Htp 4511 vfs_write

参考


関連

*1カーネル内に限りらずユーザー空間も分析できます

*2:調べ方は strace でシステムコールの所要時間を調べる - ablog 参照

*3:このような分析観点を「挟撃ちの原則」と読んでいます

*4カーネル内のどの関数ボトルネックになっているか

*5:funcgraph は bash で書かれたシェルスクリプトで内部的には ftrace を使っています