ISIS Application Documentation
prtloganalyzer | Standard View | TOC | Home | 
Analyze program execution efficiency in ISIS print.prt logs
            Description
              Categories
              Groups
              History
prtloganalyzer analyzes the content of an ISIS print.prt log file for application efficiency, frequency and validity. It reads the full contents of the ISIS log file (generally named print.prt but can be changed with command line and/or IsisPreferences files) and categorizes them by application name. Runtime statistics (run time, CPU utilization and I/O time) are computed for each applicaiton. A running total for all applications as well as each unique program are maintained. The results are provided in Pvl and comma separated value (CSV) file format for easy evaluation.
The ISIS print log file contain Pvl objects that, at a minimum, describe for each program its parameters and accounting numbers for each run. Nearly all ISIS applications write to this log at the end of their execution. Here is an small example of the contents an ISIS print.prt log file:
Object = lrowac2isis
  IsisVersion       = "3.2.1beta | 2010-03-18"
  ProgramVersion    = 2010-01-19
  ProgramPath       = /usgs/pkgs/isis3nightly2010-05-04/isis/bin
  ExecutionDateTime = 2010-05-04T14:45:04
  HostName          = blackflag
  UserName          = kbecker
  Description       = "Import LRO WAC EDR images into Isis cube format"
  Group = UserParameters
    FROM            = M109629168CE.IMG
    TO              = M109629168CE
    COLOROFFSET     = false
    COLOROFFSETSIZE = 2
    UNLUT           = true
  End_Group
  Group = Accounting
    ConnectTime = 00:00:04.0
    CpuTime     = 00:00:02.6
  End_Group
End_Object
Object = spiceinit
  IsisVersion       = "3.2.1beta | 2010-03-18"
  ProgramVersion    = 2009-07-21
  ProgramPath       = /usgs/pkgs/isis3nightly2010-05-04/isis/bin
  ExecutionDateTime = 2010-05-04T14:45:40
  HostName          = blackflag
  UserName          = kbecker
  Description       = "Determine SPICE kernels for a camera cube"
  Group = UserParameters
    FROM         = M109629168CE.vis.even.cub
    ATTACH       = TRUE
    CKSMITHED    = FALSE
    CKRECON      = TRUE
    CKPREDICTED  = FALSE
    CKNADIR      = FALSE
    SPKSMITHED   = FALSE
    SPKRECON     = TRUE
    SPKPREDICTED = FALSE
    SHAPE        = SYSTEM
    STARTPAD     = 0.0
    ENDPAD       = 0.0
  End_Group
  Group = Kernels
    NaifIkCode                = -85621
    LeapSecond                = $base/kernels/lsk/naif0009.tls
    TargetAttitudeShape       = ($base/kernels/pck/pck00009.tpc,
                                 $lro/kernels/pck/moon_080317.tf,
                                 $lro/kernels/pck/moon_assoc_me.tf)
    TargetPosition            = ($lro/kernels/tspk/moon_pa_de421_1900-2050.bp-
                                 c, $lro/kernels/tspk/de421.bsp)
    InstrumentPointing        = ($lro/kernels/ck/moc42_2009281_2009282_v01.bc,
                                 $lro/kernels/fk/lro_frames_2010034_v01.tf)
    Instrument                = $lro/kernels/ik/lro_instruments_v11.ti
    SpacecraftClock           = $lro/kernels/sclk/lro_clkcor_2010117_v00.tsc
    InstrumentPosition        = $lro/kernels/spk/fdf29_2009281_2009282_n01.bsp
    InstrumentAddendum        = $lro/kernels/iak/lro_instrumentAddendum_v03.ti
    ShapeModel                = $base/dems/ulcn2005_lpo_0003.cub
    InstrumentPositionQuality = Reconstructed
    InstrumentPointingQuality = Reconstructed
    CameraVersion             = 1
  End_Group
  Group = Accounting
    ConnectTime = 00:00:02.0
    CpuTime     = 00:00:02.2
  End_Group
End_Object
Object = lrowaccal
  IsisVersion       = "3.2.1beta | 2010-03-18"
  ProgramVersion    = 2009-07-01
  ProgramPath       = /usgs/pkgs/isis3nightly2010-05-04/isis/bin
  ExecutionDateTime = 2010-05-04T14:46:30
  HostName          = blackflag
  UserName          = kbecker
  Description       = "This program calibrates WAC images"
  Group = UserParameters
    FROM              = M109629168CE.vis.even.cub
    TO                = M109629168CE.vis.even.cal.cub
    Dark              = True
    DarkFile          = Default
    Flatfield         = True
    FlatfieldFile     = Default
    Radiometric       = True
    RadiometricType   = IOF
    RadiometricFile   = Default
    SpecialPixels     = True
    SpecialPixelsFile = Default
  End_Group
  Group = Accounting
    ConnectTime = 00:00:02.0
    CpuTime     = 00:00:01.3
  End_Group
End_Object
Object = cam2map
  IsisVersion       = "3.2.1beta | 2010-03-18"
  ProgramVersion    = 2009-08-10
  ProgramPath       = /usgs/pkgs/isis3nightly2010-05-04/isis/bin
  ExecutionDateTime = 2010-05-04T14:48:16
  HostName          = blackflag
  UserName          = kbecker
  Description       = "Convert camera image to a map projection"
  Group = UserParameters
    FROM         = M109629168CE.vis.even.cal.cub
    MAP          = ../Truth/M109629168CE.vis.pair.cub
    TO           = M109629168CE.vis.even.proj.cub
    MATCHMAP     = true
    PIXRES       = CAMERA
    DEFAULTRANGE = MINIMIZE
    LONSEAM      = AUTO
    INTERP       = CUBICCONVOLUTION
  End_Group
  Group = Mapping
    TargetName         = Moon
    ProjectionName     = Sinusoidal
    EquatorialRadius   = 1737400.0 <meters>
    PolarRadius        = 1737400.0 <meters>
    LatitudeType       = Planetocentric
    LongitudeDirection = PositiveEast
    LongitudeDomain    = 360
    MinimumLatitude    = 68.9554409639
    MaximumLatitude    = 74.97852210253
    MinimumLongitude   = 295.368508761
    MaximumLongitude   = 303.5219691619
    CenterLongitude    = 3.000000000000e+02
  End_Group
  Group = Accounting
    ConnectTime = 00:39:12.0
    CpuTime     = 00:39:10.5
  End_Group
End_Object
Object = cam2map
  IsisVersion       = "3.2.1beta | 2010-03-18"
  ProgramVersion    = 2009-08-10
  ProgramPath       = /usgs/pkgs/isis3nightly2010-05-04/isis/bin
  ExecutionDateTime = 2010-05-04T15:27:42
  HostName          = blackflag
  UserName          = kbecker
  Description       = "Convert camera image to a map projection"
  Group = UserParameters
    FROM         = M109629168CE.vis.odd.cal.cub
    MAP          = ../Truth/M109629168CE.vis.pair.cub
    TO           = M109629168CE.vis.odd.proj.cub
    MATCHMAP     = true
    PIXRES       = CAMERA
    DEFAULTRANGE = MINIMIZE
    LONSEAM      = AUTO
    INTERP       = CUBICCONVOLUTION
  End_Group
  Group = Mapping
    TargetName         = Moon
    ProjectionName     = Sinusoidal
    EquatorialRadius   = 1737400.0 <meters>
    PolarRadius        = 1737400.0 <meters>
    LatitudeType       = Planetocentric
    LongitudeDirection = PositiveEast
    LongitudeDomain    = 360
    MinimumLatitude    = 68.9554409639
    MaximumLatitude    = 74.97852210253
    MinimumLongitude   = 295.368508761
    MaximumLongitude   = 303.5219691619
    CenterLongitude    = 3.000000000000e+02
  End_Group
  Group = Accounting
    ConnectTime = 00:39:28.0
    CpuTime     = 00:39:26.7
  End_Group
End_Object
Object = automos
  IsisVersion       = "3.2.1beta | 2010-03-18"
  ProgramVersion    = 2009-10-19
  ProgramPath       = /usgs/pkgs/isis3nightly2010-05-04/isis/bin
  ExecutionDateTime = 2010-05-04T16:31:56
  HostName          = blackflag
  UserName          = kbecker
  Description       = "Create a mosaic using a list of map projected cubes"
  Group = UserParameters
    FROMLIST       = proj.lis
    MOSAIC         = M109629168CE.vis.usgs.cub
    PRIORITY       = ONTOP
    GRANGE         = AUTO
    TRACK          = FALSE
    MATCHBANDBIN   = TRUE
    HIGHSATURATION = FALSE
    LOWSATURATION  = FALSE
    NULL           = FALSE
  End_Group
  Group = ImageLocation
    File        = M109629168CE.vis.even.proj.cub
    StartSample = 1
    StartLine   = 1
  End_Group
  Group = ImageLocation
    File        = M109629168CE.vis.odd.proj.cub
    StartSample = 1
    StartLine   = 1
  End_Group
  Group = Accounting
    ConnectTime = 00:00:03.0
    CpuTime     = 00:00:01.5
  End_Group
End_Object
      
      In the above example, there are 6 total programs of which 5 are unique (cam2map is run twice). The output of this application with command line prtloganalyzer from=print.prt is:
Group = Results
  Programs = 6
  Unique   = 5
  Included = 0
  Excluded = 0
  Valid    = 6
  Errors   = 0
  ZeroTime = 0
  NoData   = 0
  BadData  = 0
  Total    = 6
End_Group
Group = ProgramTotals
  Hits               = 6
  ConnectTimeMinimum = 2.00
  ConnectTimeMaximum = 2368.00
  ConnectTimeAverage = 788.50
  ConnectTimeStdDev  = 1217.2894
  CpuTimeMinimum     = 1.30
  CpuTimeMaximum     = 2366.70
  CpuTimeAverage     = 787.47
  CpuTimeStdDev      = 1217.0055
  IOTimeMinimum      = -0.20
  IOTimeMaximum      = 1.50
  IOTimeAverage      = 1.03
  IOTimeStdDev       = 0.6743
End_Group
      
      The following table summarizes the definitions of the keywords and values found in the Results group. This group provides a count summary of applications categorized to indicate the applications processing status as found in the log file.
| Keyword | Description | 
|---|---|
| Programs | Provides the total number of all applications found in the print log file. | 
| Unique | Count of the number of unique programs found in the print log. Programs with the same name are tabulated together to form an indication of a single programs efficiency. | 
| Included | The application provides two ways to include only named applications (see the INCLUDE and INCLUDEFROM parameters). This keyword provides a count of all the included programs analyzed. | 
| Excluded | The application provides two ways to exclude specific applications (see the EXCLUDE and EXCLUDEFROM parameters). This keyword provides a count of all excluded programs from the print log file. | 
| Valid | This keyword provides a count of the number of valid programs that were found in the print log file. These are application Pvl objects that do not contain an Errors group. | 
| ZeroTime | This keyword provides a count of the number of applications that have 0 times for ConnectTime and CpuTime in the Accounting group of an application. These occurances are not included in the efficiency analysis as the statistical results are skewed by them. | 
| NoData | There are times when an application may not contain an Accounting group. These are rare occasions and may not ever occur in the wild, but a count is provided here. | 
| BadData | Occasionally something can go wrong with the print log file and it can become corrupted or the application did not format the contents properly. This parameter counts the number of occurances where some of the data is invalid or missing entitirely. | 
| Total | This number provides the total number of valid programs found in the given print log file. This number includes only those used in the ProgramTotals group in the results. | 
The ProgramTotals group provides the runtime numbers for all the programs. This will give an indication of performance for all applications included in the analysis. The SUMMARY parameter indicates the name of a file that will included the Results and ProgramTotals groups and a ProgramTotals group for each unique set of applications, such as cam2map. The following table describes the meaning of the keywords contained in the ProgramTotals group above.
All units of times are in seconds unless otherwise indicated. All these values are computed from the Accounting group in each application object entry in the log file. These numbers are computed from keywords in this group. The ConnectTime keyword is used to compute runtime values. The CpuTime keyword is used to compute CPU values. The I/O values are computed using the difference between the connect times and the cpu times. Not real scientific but is the best we can do given the data to work with. I/O times may also include wait states during the run of the application other than disk I/O. Our assumption is that I/O dominates this difference.
| Keyword | Description | 
|---|---|
| Hits | Provides the total number of all applications found in the print log file. Should be the same as the Total keyword in the Results group. | 
| ConnectTimeMinimum | Indicates the minimum time an application took to complete. | 
| ConnectTimeMaximum | Indicates the maximum time an application took to complete. | 
| ConnectTimeAverage | Indicates the average time an application took to complete. | 
| ConnectTimeStdDev | Indicates the standard deviation of the time an application took to complete. | 
| CpuTimeMinimum | Indicates the minimum cpu time an application used. | 
| CpuTimeMaximum | Indicates the maximum cpu time an application used. | 
| CpuTimeAverage | Indicates the average cpu time an application used. | 
| CpuTimeStdDev | Indicates the standard deviation of the cpu time an application used. | 
| IOTimeMinimum | Indicates the minimum I/O time an application used. | 
| IOTimeMaximum | Indicates the maximum I/O time an application used. | 
| IOTimeAverage | Indicates the average I/O time an application used. | 
| IOTimeStdDev | Indicates the standard deviation of the I/O time an application used. | 
Finally, the name of the file specified in the LOG parameter will contain a flat file of comma separated values (CSV) for each program. This files is intended to be used to plot the computed values for each of the applications. The following is the contents of the LOG file.
Program,From,To,ExecutionDateTime,ConnectTime,CpuTime,IOTime
lrowac2isis,M109629168CE.IMG,M109629168CE,2010-05-04T14:45:04,4.00,2.60,1.40
spiceinit,M109629168CE.vis.even.cub,NULL,2010-05-04T14:45:40,2.00,2.20,-0.20
lrowaccal,M109629168CE.vis.even.cub,M109629168CE.vis.even.cal.cub,2010-05-04T14:46:30,2.00,1.30,0.70
cam2map,M109629168CE.vis.even.cal.cub,M109629168CE.vis.even.proj.cub,2010-05-04T14:48:16,2352.00,2350.50,1.50
cam2map,M109629168CE.vis.odd.cal.cub,M109629168CE.vis.odd.proj.cub,2010-05-04T15:27:42,2368.00,2366.70,1.30
automos,NULL,NULL,2010-05-04T16:31:56,3.00,1.50,1.50
      
      As you can see the file contains certain fields from each application selected from the print log file. The name of the program is provided as well as the FROM and TO parameters to the program if they exist. It either one does not exist, a NULL values is written (some programs don't have a FROM or a TO parameter). The time the program was executed/started is also provided. This parameter provides the ability to plot a time based parameter. The connect, CPU and I/O times then follow.
| Name | Description | 
|---|---|
| FROM | Name of an ISIS print.prt log file | 
| INCLUDEFROM | File containing list of application names to include in analysis | 
| EXCLUDEFROM | File containing list of application names to exclude in analysis | 
| SUMMARY | Output file containing summarization of each unique program in print file analysis | 
| LOG | Writes the specifics for all valid programs to this file | 
| Name | Description | 
|---|---|
| INCLUDE | Application names to include in analysis | 
| EXCLUDE | Application names to exclude in analysis | 
This parameter provides the name of the ISIS print log file. The name is typically "print.prt" but can vary. Note that many different print.prt files can be concatenated together in one file so that analysis can be performed on many files. One such way to concatenate print files is to use the UNIX cat command to combine two or more files to a single file. The general form is cat file1 file2 file3 > catfile.
| Type | filename | 
|---|---|
| File Mode | input | 
| Default Path | . | 
| Internal Default | print.prt | 
| Filter | *.prt | 
This parameter is optional and can be used to list the names of programs that will be included in from the print file. This is handy to limit the full-up analysis to a specific set of applications. The file should contain the name of a single application on each line.
If applications of the same name exist in the exclude list as well, exclusions always takes precedence over the inclusions.
| Type | filename | 
|---|---|
| File Mode | input | 
| Internal Default | None | 
| Filter | *.lis | 
This parameter is optional and can be used to list the names of programs that will be excluded in from the print file. This is handy to exlude programs that are mostly benign in nature (.e.g., getkey) that may skew the analysis. The file should contain the name of a single application on each line.
If applications of the same name exist in the include list as well, exclusions always takes precedence over the inclusions.
| Type | filename | 
|---|---|
| File Mode | input | 
| Internal Default | None | 
| Filter | *.lis | 
If specifed the file name given for this parameter will contain the reported Results and ProgramTotals groups as well as a ProgramTotals group but with the name for each unique application set.
| Type | filename | 
|---|---|
| File Mode | output | 
| Internal Default | None | 
| Filter | *.dat | 
If specified, the file name given for this parameter will contain a comma separated value format listing for each application included in the analysis. See the main documentation for details on the contents of this file.
| Type | filename | 
|---|---|
| File Mode | output | 
| Internal Default | None | 
This parameter is a convenient way to provided a list of applications to include in the analysis. Expected is a comma separated list of ISIS application names. All other applications that occur in the print log are excluded from the analysis.
| Type | string | 
|---|---|
| Internal Default | None | 
This parameter is a convenient way to provided a list of applications to exclude in the analysis. Expected is a comma separated list of ISIS application names. All other applications that occur in the print log are included in the analysis.
| Type | string | 
|---|---|
| Internal Default | None | 
| Kris Becker | 2010-09-07 | Original version |