Python version of DFC RPC Trace Analysis tool

Visibility: Open to anyone

The attached program is a python version of the DFC RPC trace analysis program. It effectively combines the two previous awk scripts: traceD6.awk and trace_rpc_histD6.awk (attached the following note).

 

This supports two analysis:

 

1. dump of RPC's (default), and

2. profile of the RPC's.

 

The basic invocation looks as follows:

 

bash$ python traceD6.py your.DFC.trace.file.txt | more
usxxbuechembp2:12-20-2012 bueche$ python traceD6.py sample.DFC.trace.txt | more

931.652 & 0.032 & [Worker:ExportAction:#17] & getBlock & 
931.684 & 0.031 & [Worker:ExportAction:#17] & getBlock & 
931.715 & 0.015 & [Worker:ExportAction:#17] & getBlock & 
931.730 & 0.032 & [Worker:ExportAction:#17] & getBlock & 
931.746 & 0.031 & [Worker:ExportAction:#4] & getBlock & 
931.762 & 0.015 & [Worker:ExportAction:#17] & getBlock & 
931.777 & 0.016 & [Worker:ExportAction:#4] & getBlock & 
931.777 & 0.016 & [Worker:ExportAction:#17] & getBlock & 
931.793 & 0.031 & [Worker:ExportAction:#4] & getBlock & 
931.793 & 0.031 & [Worker:ExportAction:#17] & getBlock & 
931.824 & 0.000 & [Worker:ExportAction:#12] & EXEC_QUERY & select d_status,d_category from dm_dbo.ks_d_status, FOR_UPDATE=F, BATCH_HINT=50, BOF_DQL=T, FLUSH_BATCH=-1]],50,true,true) 
931.824 & 0.000 & [Worker:ExportAction:#12] & multiNext & 
931.824 & 0.016 & [Worker:ExportAction:#17] & getBlock & 
931.824 & 0.016 & [Worker:ExportAction:#4] & getBlock & 
931.840 & 0.031 & [Worker:ExportAction:#17] & getBlock & 
931.855 & 0.016 & [Worker:ExportAction:#4] & getBlock & 
931.871 & 0.016 & [Worker:ExportAction:#17] & getBlock & 
931.871 & 0.016 & [Worker:ExportAction:#4] & getBlock & 
931.887 & 0.015 & [Worker:ExportAction:#17] & getBlock & 
931.730 & 0.172 & [Worker:ExportAction:#10] & getBlock & 
931.902 & 0.016 & [Worker:ExportAction:#12] & IsCurrent & 3d0234ba82b23c1b
931.887 & 0.031 & [Worker:ExportAction:#4] & getBlock & 
931.918 & 0.016 & [Worker:ExportAction:#12] & SysObjGetPermit & 090234ba8026f283
931.902 & 0.032 & [Worker:ExportAction:#17] & getBlock & 
931.934 & 0.000 & [Worker:ExportAction:#12] & SysObjGetXPermit & 090234ba8026f283

 

to run the profile on the DFC RPC trace:

 

usxxbuechembp2:01232013 bueche$ python traceD6.py sample.dfc.trace.txt  -profile


****** PROFILE OF rpc CALLS *****
     0.592               0.042                  14          AUTHENTICATE_USER
     0.017               0.002                   7          BEGIN_TRANS
     0.059               0.008                   7          END_TRANS
   159.554               1.308                 122          EXEC_QUERY
     0.056               0.003                  17          FETCH
     0.508               0.015                  34          FETCH_CONTENT
     0.060               0.007                   8          FETCH_STORAGE
     5.859               0.225                  26          GET_DD_OBJECT
     0.004               0.002                   2          GET_DOCBASE_CONFIG
     0.009               0.001                  14          GET_ERRORS
     0.052               0.004                  14          GET_SERVER_CONFIG
     0.003               0.003                   1          GET_TYPES_CHANGED
     0.095               0.003                  37          IsCurrent
     0.022               0.001                  34          KILL_PULLER
     0.028               0.006                   5          LOCK_OBJECT
    12.495               0.367                  34          MAKE_PULLER
     0.306               0.006                  51          NORPC
     0.071               0.005                  14          SESSION_SETUP
     4.281               0.061                  70          SysObjFullFetch
     0.331               0.010                  34          SysObjGetPermit
     0.116               0.003                  34          SysObjGetXPermit
     0.001               0.001                   2          TIME
    85.867               0.062                1375          getBlock
     0.084               0.001                 101          multiNext
     5.573               0.398                  14          newSessionByAddr


**** QUERY RESPONSE SORTED IN DESCENDING ORDER ****

11.882          select r_object_id from dm_folder where FOLDER(ID('0b0234c7800002f0'),descend) order by 1, FOR_UPDATE=T, BATCH_HINT=50, BOF_DQL=T, FLUSH_BATCH=-1]],50,true,true) 
5.439          select r_object_id from dm_folder where FOLDER(ID('0b0234c7800002f0'),descend) order by 1, FOR_UPDATE=T, BATCH_HINT=50, BOF_DQL=T, FLUSH_BATCH=-1]],50,true,true) 
4.764          select r_object_id from dm_folder where FOLDER(ID('0b0234c78000023c'),descend) order by 1, FOR_UPDATE=T, BATCH_HINT=50, BOF_DQL=T, FLUSH_BATCH=-1]],50,true,true) 
:
:

 

This python version runs faster than the earlier awk versions. The profile, in particular, is significantly faster. The sample trace file (file.txt) was about 22 M bytes.

 

Eds-MacBook-Air:trace edbueche$ time awk -f trace_rpc_histD6.awk < file.txt > t.txt
real          0m39.676s
user          0m32.235s
sys          0m7.435s
Eds-MacBook-Air:trace edbueche$ time awk -f traceD6.awk < file.txt > t2.txt
real          0m1.960s
user          0m1.923s
sys          0m0.029s

 

vs. the Python version:

 

 

 

Eds-MacBook-Air:traceD6 edbueche$ time python traceD6.py file.txt > t.txt
real          0m0.656s
user          0m0.610s
sys          0m0.041s
Eds-MacBook-Air:traceD6 edbueche$ time python traceD6.py file.txt -profile > t1.txt
real          0m0.859s
user          0m0.817s
sys          0m0.029s 

 

Python ships natively for MacOS and Linux (but dependong on your version, you may need an upgrade, this program was developed with version 2.6.x). For windows you can find a version here.

Enjoy

Ed