ZFS の VOP 処理時間測定用 dscript

さて、なにかアプリを実行していて、ZFS はどこで処理時間がかかっているのか、気になることがあると思います。それぞれの VOP がどれだけ時間を消費しているのか表示する dscript を紹介します。

このスクリプト (zfs_get_vop_times.d) は、それぞれの VOP が呼ばれた回数、平均の処理時間、のべの処理時間を示します。システム上にあるすべての ZFS ファイルシステムが表示されます。表示は次のようになります。

# ./zvop_times.d 
dtrace:script './zvop_times.d' matched 66 probes
\^C
CPU     ID                    FUNCTION:NAME
17      2                             :END 
ZFS COUNT


zfs_fsync                                                        61
zfs_write                                                       494
zfs_read                                                        520

ZFS AVG TIME

zfs_read                                                    2737251
zfs_write                                                   6992704
zfs_fsync                                                  73401109


ZFS SUM TIME

zfs_read                                                 1423370640
zfs_write                                                3454396080
zfs_fsync                                                4477467680

このスクリプト (zvop_times_fsid.d) は、先ほどのスクリプトと同じ情報を、1 つのファイルシステムについてだけ表示します。表示対象のファイルシステムは、FSID を入力するだけで選べます。

最後に、このスクリプト (zvop_times_fsid_large.d) は、2 番目のスクリプトと同じこと (FSID ごとの分析) を行いますが、ZFS の VOP 呼び出しが X 時間を超えた場合、スタックとクォンタイズの情報も出力します。X は引数で渡します。非常に時間がかかっている呼び出しがないかどうか、確認する手助けになります。出力は次のようになります (前の例と同じ表示になる部分は省略)。

# ./zvop_times_fsid_large.d 0x7929404d 0xb3d52b08 50000000
dtrace:script './zvop_times_fsid_large.d' matched 123 probes
CPU     ID                    FUNCTION:NAME
14  35984                  zfs_read:return 
genunix`fop_read+0x20
genunix`read+0x29c
unix`syscall_trap32+0x1e8

16  35994               zfs_putpage:return 
genunix`fop_putpage+0x1c
nfssrv`rfs3_commit+0x110
nfssrv`common_dispatch+0x588
rpcmod`svc_getreq+0x1ec
rpcmod`svc_run+0x1e8
nfs`nfssys+0x1b8
unix`syscall_trap32+0x1e8

18  35994               zfs_putpage:return 
genunix`fop_putpage+0x1c
nfssrv`rfs3_commit+0x110
nfssrv`common_dispatch+0x588
rpcmod`svc_getreq+0x1ec
rpcmod`svc_run+0x1e8
nfs`nfssys+0x1b8
unix`syscall_trap32+0x1e8

12  35972                 zfs_fsync:return 
genunix`fop_fsync+0x14
nfssrv`rfs4_createfile+0x500
nfssrv`rfs4_do_opennull+0x44
nfssrv`rfs4_op_open+0x380
nfssrv`rfs4_compound+0x208
nfssrv`rfs4_dispatch+0x11c
nfssrv`common_dispatch+0x154
rpcmod`svc_getreq+0x1ec
rpcmod`svc_run+0x1e8
nfs`nfssys+0x1b8
unix`syscall_trap32+0x1e8

\^C


zfs_fsync                                         
value  ------------- Distribution ------------- count    
        33554432 |                                         0        
        67108864 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1        
       134217728 |                                         0        

zfs_putpage                                       
value  ------------- Distribution ------------- count    
        33554432 |                                         0        
        67108864 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2        
       134217728 |                                         0        

zfs_read                                          
value  ------------- Distribution ------------- count    
        67108864 |                                         0        
       134217728 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1        
       268435456 |                                         0     

リンク先のスクリプトは自由に使ったり編集したりしてみてください。

Comments:

Post a Comment:
Comments are closed for this entry.
About

erickustarz

Search

Categories
Archives
« April 2015
SunMonTueWedThuFriSat
   
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
  
       
Today