Hatena::ブログ(Diary)

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

2016-08-08

zone_reclaim_mode=1 だと NUMA のリモートノードのゾーンからページが割当られない?

zone_reclaim_mode=1 だと、NUMA ノードのゾーンごとに wmark_{min|low|high} が計算され、各ゾーンで空きメモリが wmark_low を下回るとページ回収が始まると理解している。

zone_reclaim_mode=1 の場合、ページ回収が追いつかないとリモートノードのゾーンからメモリが割当てられずに "page allocation failure" が発生するのではないかという話を聞いたので調べてみたが、以下の通り、ローカルノードのゾーンからメモリで割当できない場合はリモートノードのゾーンからメモリから割当てられそう。

When vm.zone_reclaim_mode is enabled, the kernel attempts to free up or reclaim pages from the target node's memory before going off-node for the allocation. For example, these pages might be cached file pages or other applications' pages that have not been referenced for a relatively long time. The allocation overflows only if the attempt to reclaim local pages fails.

So, why does Linux provide this option? What is the benefit?

For some long running applications—for example, high performance technical computing applications—the overall runtime can vary dramatically, based on the locality of their memory references. When such an application is started, even with well-thought out memory policies, a given node's memory could be filled up with page cache pages from previous jobs or previous phases of the application. Enabling vm.zone_reclaim_mode allows the application to reclaim those cached file pages for its own use, rather than going off-node. This most likely benefits the application’s performance over its remaining lifetime.

The default setting for vm.zone_reclaim_mode is enabled if any of the distances in the SLIT are greater than a fixed threshold, and disabled otherwise. Currently, the threshold in most shipping distros is a SLIT value of 20, and this is the case for both Red Hat Enterprise Linux 5 and Red Hat Enterprise Linux 6. (The upstream kernel now uses a value of 30 as the threshold; this will appear in newer distro versions.) For a server that does not supply a populated SLIT, vm.zone_reclaim_mode defaults to disabled, because the remote distances in the kernel's default SLIT are all 20. If the default setting is not appropriate for your workload, you can change it with the following command:

sysctl –w vm.zone_reclaim_mode={0|1}

http://h20564.www2.hpe.com/hpsc/doc/public/display?docId=emr_na-c03261871

追記(2016/08/18):

Linux Kernel*1ソースコードでも確認してみた。mm/page_alloc.c#get_page_from_freelist を読むと、zone_reclaim_mode=0 の場合はページ回収をスキップしている模様。


/*
 * get_page_from_freelist goes through the zonelist trying to allocate
 * a page.
 */
static struct page *
get_page_from_freelist(gfp_t gfp_mask, nodemask_t *nodemask, unsigned int order,
		struct zonelist *zonelist, int high_zoneidx, int alloc_flags,
		struct zone *preferred_zone, int migratetype)
{
	struct zoneref *z;
	struct page *page = NULL;
	int classzone_idx;
	struct zone *zone;
	nodemask_t *allowednodes = NULL;/* zonelist_cache approximation */
	int zlc_active = 0;		/* set if using zonelist_cache */
	int did_zlc_setup = 0;		/* just call zlc_setup() one time */

	classzone_idx = zone_idx(preferred_zone);
zonelist_scan:
	/*
	 * Scan zonelist, looking for a zone with enough free.
	 * See also cpuset_zone_allowed() comment in kernel/cpuset.c.
	 */
	for_each_zone_zonelist_nodemask(zone, z, zonelist,
						high_zoneidx, nodemask) {
		if (IS_ENABLED(CONFIG_NUMA) && zlc_active &&
			!zlc_zone_worth_trying(zonelist, z, allowednodes))
				continue;
		if ((alloc_flags & ALLOC_CPUSET) &&
			!cpuset_zone_allowed_softwall(zone, gfp_mask))
				continue;
		/*
		 * When allocating a page cache page for writing, we
		 * want to get it from a zone that is within its dirty
		 * limit, such that no single zone holds more than its
		 * proportional share of globally allowed dirty pages.
		 * The dirty limits take into account the zone's
		 * lowmem reserves and high watermark so that kswapd
		 * should be able to balance it without having to
		 * write pages from its LRU list.
		 *
		 * This may look like it could increase pressure on
		 * lower zones by failing allocations in higher zones
		 * before they are full.  But the pages that do spill
		 * over are limited as the lower zones are protected
		 * by this very same mechanism.  It should not become
		 * a practical burden to them.
		 *
		 * XXX: For now, allow allocations to potentially
		 * exceed the per-zone dirty limit in the slowpath
		 * (ALLOC_WMARK_LOW unset) before going into reclaim,
		 * which is important when on a NUMA setup the allowed
		 * zones are together not big enough to reach the
		 * global limit.  The proper fix for these situations
		 * will require awareness of zones in the
		 * dirty-throttling and the flusher threads.
		 */
		if ((alloc_flags & ALLOC_WMARK_LOW) &&
		    (gfp_mask & __GFP_WRITE) && !zone_dirty_ok(zone))
			goto this_zone_full;

		BUILD_BUG_ON(ALLOC_NO_WATERMARKS < NR_WMARK);
		if (!(alloc_flags & ALLOC_NO_WATERMARKS)) {
			unsigned long mark;
			int ret;

			mark = zone->watermark[alloc_flags & ALLOC_WMARK_MASK];
			if (zone_watermark_ok(zone, order, mark,
				    classzone_idx, alloc_flags))
				goto try_this_zone;

			if (IS_ENABLED(CONFIG_NUMA) &&
					!did_zlc_setup && nr_online_nodes > 1) {
				/*
				 * we do zlc_setup if there are multiple nodes
				 * and before considering the first zone allowed
				 * by the cpuset.
				 */
				allowednodes = zlc_setup(zonelist, alloc_flags);
				zlc_active = 1;
				did_zlc_setup = 1;
			}

			if (zone_reclaim_mode == 0 || ★ zone_reclaim_modeが0→ ページ回収をスキップ
			    !zone_allows_reclaim(preferred_zone, zone))
				goto this_zone_full;

			/*
			 * As we may have just activated ZLC, check if the first
			 * eligible zone has failed zone_reclaim recently.
			 */
			if (IS_ENABLED(CONFIG_NUMA) && zlc_active &&
				!zlc_zone_worth_trying(zonelist, z, allowednodes))
				continue;

			ret = zone_reclaim(zone, gfp_mask, order);
			switch (ret) {
			case ZONE_RECLAIM_NOSCAN:
				/* did not scan */
				continue;
			case ZONE_RECLAIM_FULL:
				/* scanned but unreclaimable */
				continue;
			default:
				/* did we reclaim enough */
				if (zone_watermark_ok(zone, order, mark,
						classzone_idx, alloc_flags))
					goto try_this_zone;

				/*
				 * Failed to reclaim enough to meet watermark.
				 * Only mark the zone full if checking the min
				 * watermark or if we failed to reclaim just
				 * 1<<order pages or else the page allocator
				 * fastpath will prematurely mark zones full
				 * when the watermark is between the low and
				 * min watermarks.
				 */
				if (((alloc_flags & ALLOC_WMARK_MASK) == ALLOC_WMARK_MIN) ||
				    ret == ZONE_RECLAIM_SOME)
					goto this_zone_full;

				continue;
			}
		}

try_this_zone:
		page = buffered_rmqueue(preferred_zone, zone, order,
						gfp_mask, migratetype);
		if (page)
			break; ★ ページを確保できたらループを抜ける
this_zone_full:
		if (IS_ENABLED(CONFIG_NUMA))
			zlc_mark_zone_full(zonelist, z);
	}

	if (unlikely(IS_ENABLED(CONFIG_NUMA) && page == NULL && zlc_active)) {
		/* Disable zlc cache for second zonelist scan */
		zlc_active = 0;
		goto zonelist_scan;
	}

	if (page)
		/*
		 * page->pfmemalloc is set when ALLOC_NO_WATERMARKS was
		 * necessary to allocate the page. The expectation is
		 * that the caller is taking steps that will free more
		 * memory. The caller should avoid the page being used
		 * for !PFMEMALLOC purposes.
		 */
		page->pfmemalloc = !!(alloc_flags & ALLOC_NO_WATERMARKS);

	return page;
}

関連

*1:RHEL7系で採用されている 3.10 で確認

2016-06-29

Poderosa から Cygwin に接続するとバックスペースが効かない

別件でいろいろ試した時に接続時のターミナル種別を kterm にしていたからだった。vt100 や xterm にするとバックスペースが効いた。

f:id:yohei-a:20160629162352p:image

Cygwinで1行でプロンプトを表示する

.bashrc でシェル変数 PS1 を設定する。

  • .bashrc 設定例
PS1='\d \t \W\ $'

  • 実行結果
Wed Jun 29 15:46:40 Poderosa\ $

参考

bash の場合 PS1 という名前のシェル変数です。なぜ PS1 なのかは、マニュアルによると "The primary prompt string"=プライマリ(1番目の)プロンプト文だからです。"The secondary prompt string"という2番目のプロンプト文を示す PS2 もあります。行継続用プロンプト文です。『 \ 』を使って次行に引き渡されたときの指定です。

プロンプトの確認や設定 - Pocketstudio.jp Linux Wiki

2016-06-15

strace の -y や -yy でFD番号と共にファイルパスやIPアドレス・ポート番号を表示する

strace を使う場合、プロセスが起動している間に lsof や /proc/[pid]/fd でファイルディスクリプタFD)番号とファイルパスの対応を確認しておかないと、read(17, ... などと出力されている場合に、17 のファイルパスがわからなくなりますが*1

  • strace 4.7 (2012年5月リリース) から -y でFD番号と対応するファイルパス
Noteworthy changes in release 4.7
=================================

...

* Improvements
  * Added x32 personality support (x86_64 architecture).
  * Added -y and -P options to print file descriptor paths and
    filter by those paths.
Noteworthy changes in release 4.10 (2015-03-06)
===============================================

* Improvements
  * Added -yy option to print protocol and address information associated with
    socket descriptors.

を表示してくれます。これは便利!


インストール

$ tar xfvJ strace-4.12.tar.xz 
$ cd strace-4.12
$ ./configure
$ make
$ ./strace -h|grep '\-y'
  -y             print paths associated with file descriptor arguments
  -yy            print protocol specific information associated with socket file descriptors

実行例

  • -y でFD番号とともにファイルパスを表示する
$ ./strace -y  ls > /dev/null
execve("/bin/ls", ["ls"], [/* 23 vars */]) = 0

...

open("/etc/ld.so.cache", O_RDONLY)      = 3</etc/ld.so.cache>
fstat(3</etc/ld.so.cache>★, {st_mode=S_IFREG|0644, st_size=41296, ...}) = 0
mmap(NULL, 41296, PROT_READ, MAP_PRIVATE, 3</etc/ld.so.cache>, 0) = 0x7f2de6449000
close(3</etc/ld.so.cache>)              = 0

FD番号"3"のパス"/etc/ld.so.cache"が表示されている。


参考

       -y          Print paths associated with file descriptor arguments.

       -yy         Print ip:port pairs associated with socket file
                   descriptors.
Add ability to print file descriptor paths and filter by those paths

...

(usage, main): Implement handling of -y and -P options.
* strace.1: Add descriptions of -y and -P options.
Add -yy option: print ip and port associated with socket descriptors
When two ore more -y options are given, print local and remote ip:port
pairs associated with socket descriptors. This implementation uses
NETLINK_INET_DIAG for sockaddr lookup; it's based on the patch
prepared by Zubin Mithra as a part of his GSoC 2014 strace project.

関連

nfsiostat で NFS の I/O レイテンシや IOPS を調べる

NFS で iostat の await と svctm のような情報を取れるツールが欲しいと思っていたら nfsiostat という素敵なツールを見つけた。await にあたるのが avg exe (ms)、svctm にあたるのが avg RTT (ms) だと思う。

iostat の await と svctm の意味は Linux の iostat の出力結果を銀行のATMに例えて説明してみる - ablog 参照。


書式

$ nfsstat <interval>

実行例

  • ops/s: 秒間の read または write リクエストの発行回数
  • kB/s: 1秒間に read または write されたサイズ(KB)
  • kB/op: 1回の read または write の秒間の平均サイズ(KB)
  • avg RTT (ms): カーネルが RPC リクエストを発行してから応答までの時間(単位:1/1000秒)。おそらく、iostat の svctm に近い感じかと。
  • avg exe (ms): NFS Clientカーネルに RPC リクエストを発行して完了するまでの時間(単位:1/1000秒)。avg RTT (ms) を含む。おそらく、iostat の await に近い感じかと。
$ nfsiostat 5                                                                                                                                        

******:/backup/ mounted on /backup:

   op/s         rpc bklog
   0.00            0.00
read★:             ops/s            kB/s           kB/op         retrans         avg RTT (ms)★    avg exe (ms)0.000           0.000           0.000        0 (0.0%)           0.000           0.000
write★:            ops/s            kB/s           kB/op         retrans         avg RTT (ms)    avg exe (ms)
                  0.000           0.000           0.000        0 (0.0%)           0.000           0.000

...


補足

/proc/self/mountstats から情報を取得しているので、nfsiostat がなくても /proc/self/mountstats を定期的に記録しておけば同じことができそう。Python スクリプトを置くだけなので、そんなことをしないといけない環境は少ないと思うが。

  • strace より
$ strace -e open nfsiostat 2>&1|grep /proc                                                                                                          
open("/proc/meminfo", O_RDONLY|O_CLOEXEC) = 3
open("/proc/self/mountstats", O_RDONLY) = 3
#!/usr/bin/python
# -*- python-mode -*-
"""Emulate iostat for NFS mount points using /proc/self/mountstats ★
"""

...

def iostat_command(name):
    """iostat-like command for NFS mount points
    """
    mountstats = parse_stats_file('/proc/self/mountstats') ★

作者

作者は Linux カーネル開発者(元NetApp、現ORACLE)の Chuck Lever で、Linux NFS と FedFS の実装をしているようです。

30 週に渡り多彩な Linux カーネル開発者を紹介していくシリーズ、今週は OracleChuck Lever に話を聞きました。彼は Linux NFS と FedFS の実装の仕事をしていますが、Linux に関わるようになったのはミシガン大学に在学中でした。彼から Linux 初心者へのスペシャル アドバイスがあります。コンピューター史上最大の共同開発プロジェクトの一員の面白い見識を、ぜひどうぞ。

30人のLinuxカーネル開発者:Chuck Lever


参考

NAME

       nfsiostat   -   Emulate   iostat   for   NFS   mount   points   using
       /proc/self/mountstats

..

       <mount_point>
              If one or more <mount point> names are specified, statistics
              for only these mount points will be displayed.  Otherwise, all
              NFS mount points on the client are listed.

       The meaning of each column of nfsiostat's output is the following:
               - op/s
                      This is the number of operations per second.
               - rpc bklog
                      This is the length of the backlog queue.
               - kB/s
                      This is the number of kB written/read per second.
               - kB/op
                      This is the number of kB written/read per each
                      operation.
               - retrans
                      This is the number of retransmissions.
               - avg RTT (ms)
                      This is the duration from the time that client's
                      kernel sends the RPC request until the time it
                      receives the reply.
               - avg exe (ms)
                      This is the duration from the time that NFS client
                      does the RPC request to its kernel until the RPC
                      request is completed, this includes the RTT time
                      above.

ソース

*1:ソケットの場合は /proc/net/tcp や /proc/net/udp でソケットのIPアドレスとポート番号を確認しておく必要がある

2016-06-12

よく使う strace のオプション

Linux で strace を使ってシステムコールのトレースを調べる時によく使うオプションをメモ。

特にお気に入りのオプションは -T、-c、-ff & -o です。


書式

システムコールを詳細に追う
    • tt: 行頭にタイムスタンプを出力(マイクロ秒)
    • T: 行末にシステムコール内での所要時間を出力(マイクロ秒)
    • ff: 子プロセスのシステムコールもトレースし、-o との併用でプロセス(スレッド)毎に別ファイルに出力
    • o: 指定したファイル名に出力。-ff と併用すると、ファイル名.<PID> に出力
    • s: 出力文字数を指定。デフォルト32文字。read/write システムコールなどで読み書きした内容を全て確認したい場合は、大きくする。
    • p: プロセスIDを指定。
$ strace -Ttt -ff -s 1500000 -o <ログ出力先ファイル名> -p <PID>
もしくは
$ strace -Ttt -ff -s 1500000 -o <ログ出力先ファイル名> <コマンド>

strace したプロセスが起動している間に /proc/[pid]/fd でファイルディスクリプタ番号とファイルパスの対応を確認しておくと、strace で read(17, ... などと出力されている場合に、17 のファイルパス、つまりどのファイルを読んでいるかが分かります。

$ ls -l /proc/[pid]/fd

4.7 (2012年5月リリース) から -y、4.12 (2016年5月リリース) から -yy オプションでファイルディスクリプタ番号をファイル名、ソケットを送信元と送信先IPアドレスとポート番号に置き換えてくれるようになっているようです。

strace -o out -y cp ubuntu-16.04-desktop-amd64.iso /tmp/blah 

We still get to keep the file descriptors, but it appends the filename of the file it was reading from! Awesome! We can see that it's reading 128KB (128 * 1024 = 131072 bytes) at a time from the source file (/home/bork/Desktop/ubuntu-16.04-desktop-amd64.iso), and writing them into the destination file (/tmp/blah). Seems reasonable!

read(3</home/bork/Desktop/ubuntu-16.04-desktop-amd64.iso>, "\315\350\5p\244\334\266\213 \2553~\37\7\330w\3125\316\360u\204P\236\255\n\244\344\264\327\213\241"..., 131072) = 131072
write(4</tmp/blah>, "\315\350\5p\244\334\266\213 \2553~\37\7\330w\3125\316\360u\204P\236\255\n\244\344\264\327\213\241"..., 131072) = 131072
read(3</home/bork/Desktop/ubuntu-16.04-desktop-amd64.iso>, "\37\367\336\377\247!\357\377\200\337wV\335\366|\232\337?\373iz\37r\376/z5\275\377\360\247\335"..., 131072) = 131072
write(4</tmp/blah>, "\37\367\336\377\247!\357\377\200\337wV\335\366|\232\337?\373iz\37r\376/z5\275\377\360\247\335"..., 131072) = 131072
read(3</home/bork/Desktop/ubuntu-16.04-desktop-amd64.iso>, "x\321/|'m\25\313o \261t^b\306\17r4~\3138j\6\4\244\3308\300E\366\364\22"..., 131072) = 131072
write(4</tmp/blah>, "x\321/|'m\25\313o \261t^b\306\17r4~\3138j\6\4\244\3308\300E\366\364\22"..., 131072) = 131072
read(3</home/bork/Desktop/ubuntu-16.04-desktop-amd64.iso>, "j\273\324\332\216\361\207\204\336\243\326\267\227\35\322\370\205\245N6+\211h\246\215\32k\336\0\r\320."..., 131072) = 131072
write(4</tmp/blah>, "j\273\324\332\216\361\207\204\336\243\326\267\227\35\322\370\

...

If you run strace with -yy, and you're doing networking, it'll resolve file descriptors into a source & destination IP address and port, like this!

This is querying my DNS server on localhost for blah.com and getting no answer.

$ strace -yy wget blah.com
recvfrom(3<UDP:[127.0.0.1:46218->127.0.1.1:53]>, "\270\222\201\205\0\1\0\0\0\0\0\0\4blah\3com\0\0\1\0\1", 2048, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("127.0.1.1")}, [16]) = 26
A useful new strace feature - Julia Evans

システムコールの種類別に集計(時間・回数)する
$ strace -fc -o <ログ出力先ファイル名> -p <PID>
もしくは
$ strace -fc -o <ログ出力先ファイル名> <コマンド>

実行例

システムコールを詳細に追う
$ ps -ef|grep [t]nslsnr
oracle    55447      1  0 Feb09 ?        00:04:00 /u01/app/12.1.0.2/grid/bin/tnslsnr MGMTLSNR -no_crs_notify -inherit
oracle    56996      1  0 Feb09 ?        00:33:21 /u01/app/12.1.0.2/grid/bin/tnslsnr LISTENER_SCAN3 -no_crs_notify -inherit
oracle    69013      1  0 Mar03 ?        01:29:18 /u01/app/12.1.0.2/grid/bin/tnslsnr LISTENER -no_crs_notify -inherit
$ ls -l /proc/55447/fd                                                                                                                        
total 0
lrwx------. 1 oracle oinstall 64 Mar 19 02:18 0 -> /dev/null
lrwx------. 1 oracle oinstall 64 Mar 19 02:18 1 -> /dev/null
l-wx------. 1 oracle oinstall 64 Mar 19 02:18 10 -> pipe:[28070704]
lrwx------. 1 oracle oinstall 64 Mar 19 02:18 11 -> socket:[28104650]
lrwx------. 1 oracle oinstall 64 Mar 19 02:18 12 -> socket:[28104651]
lrwx------. 1 oracle oinstall 64 Mar 19 02:18 13 -> socket:[28107334]
lrwx------. 1 oracle oinstall 64 Mar 19 02:18 14 -> socket:[28107317]
lrwx------. 1 oracle oinstall 64 Mar 19 02:18 15 -> socket:[28088239]
lrwx------. 1 oracle oinstall 64 Mar 19 02:18 16 -> socket:[28107433]
lrwx------. 1 oracle oinstall 64 Mar 19 02:18 17 -> socket:[28107447]
lrwx------. 1 oracle oinstall 64 Mar 19 02:18 18 -> socket:[28188383]
lrwx------. 1 oracle oinstall 64 Mar 19 02:18 19 -> socket:[28188384]
lrwx------. 1 oracle oinstall 64 Mar 19 02:18 2 -> /dev/null
lr-x------. 1 oracle oinstall 64 Mar 19 02:18 3 -> /u01/app/12.1.0.2/grid/rdbms/mesg/diaus.msb
lr-x------. 1 oracle oinstall 64 Mar 19 02:18 4 -> /proc/55447/fd
lr-x------. 1 oracle oinstall 64 Mar 19 02:18 5 -> /u01/app/12.1.0.2/grid/network/mesg/nlus.msb
lrwx------. 1 oracle oinstall 64 Mar 19 02:18 6 -> anon_inode:[eventpoll]
lr-x------. 1 oracle oinstall 64 Mar 19 02:18 7 -> pipe:[28070703]
lr-x------. 1 oracle oinstall 64 Mar 19 02:18 8 -> /u01/app/12.1.0.2/grid/network/mesg/tnsus.msb
lrwx------. 1 oracle oinstall 64 Mar 19 02:18 9 -> socket:[28104649]
$ strace -Ttt -ff -s 1500000 -o strace -p 55447
Process 55447 attached with 2 threads - interrupt to quit
^CProcess 55447 detached
Process 55470 detached
$ ls
strace.55447  strace.55470
o と ff オプションにより、スレッド別にファイルが生成されている
$ head strace.55447                                                                                                       
12:14:50.669465★タイムスタンプ(-tt) epoll_wait(6, {{EPOLLIN, {u32=39785040, u64=39785040}}}, 1024, 4294967295) = 1 <7.441963>★システムコールで使った時間(-T)
12:14:58.111594 times(NULL)             = 1506816866 <0.000013>
12:14:58.111651 getsockname(9★, {sa_family=AF_FILE, path="/var/tmp/.oracle/sMGMTLSNR"}, [29]) = 0 <0.000014> 
↑ファイルディスクリプタ番号9"socket:[28104649]"
12:14:58.111716 chmod("/var/tmp/.oracle/sMGMTLSNR", 0777) = 0 <0.000029>
12:14:58.111784 accept(9, {sa_family=AF_FILE, NULL}, [2]) = 20 <0.000019>
12:14:58.111836 fcntl(20, F_SETFD, FD_CLOEXEC) = 0 <0.000011>
12:14:58.111877 times(NULL)             = 1506816866 <0.000011>
12:14:58.111967 rt_sigaction(SIGPIPE, {SIG_IGN, ~[ILL ABRT BUS FPE SEGV USR2 TERM XCPU XFSZ SYS RTMIN RT_1], SA_RESTORER|SA_RESTART|SA_SIGINFO, 0x7f27716f9710}, {SIG_IGN, ~[ILL ABRT BUS FPE KILL SEGV USR2 TERM STOP XCPU XFSZ SYS RTMIN RT_1], SA_RESTORER|SA_RESTART|SA_SIGINFO, 0x7f27716f9710}, 8) = 0 <0.000013>
12:14:58.112057 epoll_ctl(6, EPOLL_CTL_ADD, 20, {EPOLLIN, {u32=40329456, u64=40329456}}) = 0 <0.000016>
12:14:58.112109 times(NULL)             = 1506816866 <0.000011>
システムコールの種類別に集計(時間・回数)する
$ ps -ef|grep [j]ava
oracle    10498  10412  0 Apr21 ?        11:37:56 /u01/app/emcc/agent/core/12.1.0.4.0/jdk/bin/java ...

...

$ strace -fc -o strace.log -p 10498
Process 10498 attached with 236 threads - interrupt to quit
^CProcess 10498 detached
Process 10499 detached
Process 10500 detached

...

$ cat strace.log
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 69.28    0.171635         439       391        98 futex
 15.34    0.037999        1809        21        13 restart_syscall
 10.84    0.026860          86       313           sched_yield
  4.04    0.009999        5000         2           epoll_wait
  0.40    0.001000          48        21           recvfrom
  0.06    0.000156           6        27         6 stat
  0.04    0.000106          18         6           write
  0.00    0.000000           0         4           read
  0.00    0.000000           0         7           open
  0.00    0.000000           0        11           close
  0.00    0.000000           0         8           fstat
  0.00    0.000000           0         1           poll
  0.00    0.000000           0         3           lseek
  0.00    0.000000           0         4           mprotect
  0.00    0.000000           0         1           access
  0.00    0.000000           0         2           dup2
  0.00    0.000000           0         4           socket
  0.00    0.000000           0         3           connect
  0.00    0.000000           0        13           sendto
  0.00    0.000000           0         3           recvmsg
  0.00    0.000000           0         1           bind
  0.00    0.000000           0         3           getsockname
  0.00    0.000000           0         2           setsockopt
  0.00    0.000000           0         3           getsockopt
  0.00    0.000000           0         1           uname
  0.00    0.000000           0        14           fcntl
  0.00    0.000000           0         7           rename
  0.00    0.000000           0         6         5 unlink
  0.00    0.000000           0        24           clock_gettime
------ ----------- ----------- --------- --------- ----------------
100.00    0.247755                   906       122 total

関連


参考

       -c          Count time, calls, and errors for each system call and
                   report a summary on program exit.  On Linux, this
                   attempts to show system time (CPU time spent running in
                   the kernel) independent of wall clock time.  If -c is
                   used with -f or -F (below), only aggregate totals for all
                   traced processes are kept.
...
       -ff         If the -o filename option is in effect, each processes
                   trace is written to filename.pid where pid is the numeric
                   process id of each process.  This is incompatible with
                   -c, since no per-process counts are kept.
...
       -t          Prefix each line of the trace with the time of day.

       -tt         If given twice, the time printed will include the
                   microseconds.

       -ttt        If given thrice, the time printed will include the
                   microseconds and the leading portion will be printed as
                   the number of seconds since the epoch.

       -T          Show the time spent in system calls.  This records the
                   time difference between the beginning and the end of each
                   system call.
...
       -o filename Write the trace output to the file filename rather than
                   to stderr.  Use filename.pid if -ff is used.  If the
                   argument begins with '|' or with '!' then the rest of the
                   argument is treated as a command and all output is piped
                   to it.  This is convenient for piping the debugging
                   output to a program without affecting the redirections of
                   executed programs.
...
       -p pid      Attach to the process with the process ID pid and begin
                   tracing.  The trace may be terminated at any time by a
                   keyboard interrupt signal (CTRL-C).  strace will respond
                   by detaching itself from the traced process(es) leaving
                   it (them) to continue running.  Multiple -p options can
                   be used to attach to many processes in addition to
                   command (which is optional if at least one -p option is
                   given).  -p "`pidof PROG`" syntax is supported.
...
       -s strsize  Specify the maximum string size to print (the default is
                   32).  Note that filenames are not considered strings and
                   are always printed in full.
       /proc/[pid]/fd/
              This is a subdirectory containing one entry for each file
              which the process has open, named by its file descriptor, and
              which is a symbolic link to the actual file.  Thus, 0 is
              standard input, 1 standard output, 2 standard error, and so
              on.

              For file descriptors for pipes and sockets, the entries will
              be symbolic links whose content is the file type with the
              inode.  A readlink(2) call on this file returns a string in
              the format:

                  type:[inode]