It seems VOP_RWLOCK takes a long time. "ufs_rwlock" starts at line 12, but ends at line 15611. Is there another application keeps reading/writing in your system?
-----Original Message----- From: [EMAIL PROTECTED] [mailto:[EMAIL PROTECTED] On Behalf Of Hans-Peter Sent: 2008年12月3日 21:41 To: dtrace-discuss@opensolaris.org Subject: Re: [dtrace-discuss] How to dig deeper Hello all, I added a clause to my script. sysinfo::: /self->traceme==1 && pid == $1/ { trace(execname); printf("sysinfo: timestamp : %d" , timestamp); } A subsequent trace created a file of about 19000 lines. I loaded in Excel to be able to subtrace timestamps etc. The longest jump in timestamp is between the first pair of savectx and restorectx at line 70. I count 50 savectx/restorectx calls in my trace. But the actual physical write as indicated by the sysinfo is almost at the end of the file directly after the ufs_write and fop_write call end (line 18746). 24 <- tsd_agent_get oracle timestamp 1795469946839100 24 -> ufs_lockfs_top_vop_return oracle timestamp 1795469946841500 24 <- ufs_lockfs_top_vop_return oracle timestamp 1795469946844300 24 <- ufs_lockfs_end oracle timestamp 1795469946846700 24 <- ufs_write oracle timestamp 1795469946849600 24 <- fop_write oracle timestamp 1795469946853500 57,365,700 24 | pwrite syswrite oracle sysinfo timestamp 1795469946856800 24 | pwrite writech oracle sysinfo timestamp 1795469946860200 So it seems that the actual write not the bottle neck but I attached a zip file with the excel document. Am I right in thinking that is is more an OS issue than a storage issue? Regards Hans-Peter -- This message posted from opensolaris.org _______________________________________________ dtrace-discuss mailing list dtrace-discuss@opensolaris.org
