So you're running some app, and you're curious where zfs is spending its time... here's some dscripts to figure out how much time each VOP is taking.

This one ( zfs_get_vop_times.d) grabs the number of times each VOP was called, the VOP's average time, and the total time spent in each VOP. This is for all ZFS file systems on the system. It generates output like:

# ./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

This one ( zvop_times_fsid.d) does the same as above but just for one file system - namely the one you specify via passed in FSID ints.

Lastly, this one ( zvop_times_fsid_large.d) does the same as above (tracking per FSID), but also spits out the stack and quantize information when a zfs VOP call goes over X time - where X is passed into the script. This makes it easy to see if there's some really slow calls. It generates output like (skipping the output thats the same from the above examples):

# ./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     

Feel free to play around with these scripts as well as add/subtract.