PALMS+User+Guide+-+Reading+PALMS+Calculation+Log+File+(R4)

=PALMS Calculation Log File (R4)=

===NOTE: This is a work-in-progress, incomplete and subject to change. Although this documents the specifics of the R4 version of the PALMS calculation, it is generally relevant to earlier releases as well.===

Introduction
When a calculation executes, it generates a result set and a log file that contains information on the inter workings of the calculation. The log file can be viewed by clicking the result set's "book" icon. Should the results be different that you expected (for example, too many, too few, missing data, misclassification of values, etc), reading the log file may provide insight into how you can adjust the calculations parameters.

When a calculation execution fails, the last group of lines indicates the cause of the fatal error. These lines will help the PALMS staff resolve the error. Send an email to palms@ucsd.edu providing the name of the study and the name of the result set. Do not delete the result set.

General Format of Log Entry
The general format of a log entry is:

mm/dd/yyyy hh:mm:ss Module.Method - log entry


 * Time stamps are in Pacific Time. Differences in timestamps indicates the amount of time required to complete that portion of the calculation.
 * Module.Method identifies the method (function) within the module that generated the log entry.
 * Each major module has a version number and version date which is logged when the module is executed.
 * Memory logs help PALMS staff identify low memory conditions. GC refers to the Garbage Collection process with releases unused memory

Start of Calculation Execution
The calculation's version number and initial memory conditions are logged.

2/28/2012 13:16:59 CalculationOneB.calculate - Version 4.0.0 04 Feb 2012 2/28/2012 13:16:59 CalculationOneB.calculate - Entry - Memory [MB] used:66 free:33 total:100 max:1979 2/28/2012 13:17:00 CalculationOneB.calculate - After GC - Memory [MB] used:16 free:83 total:100 max:1979

Parameter Block Values
Shows values of all parameters used in the calculation.

2/28/2012 13:17:00 CalculationOneParameterBlock - Version 4.0.0 23 Feb 2012 2/28/2012 13:17:00 Entering with following parameters acc_adult_hard = 5725 acc_adult_light = 100 acc_adult_moderate = 1953 acc_adult_veryhard = 9498 acc_bout_detect = true ......... interval = 60 merge_insert_max_seconds = 600 merge_insert_missing_trackpoints = true merge_insert_until_max = false merge_start_at_midnight = false merge_toGPS = true startDate = 2008-01-01 00:00:00 subjectid = 16dedf70-ae42-43ea-a30e-9f15e1

For Each Participant in the Study
Logs the subjectGUID (PALMS's unique identifier) and the study's participant identifier; then reads the GPS dataset, in blocks of 10,000 observations, and logs the total number of observations to be processed for this participant.

2/28/2012 13:17:00 CalculationOneB.calculate **Processing Subject 1 of 1** 2/28/2012 13:17:00 CalculationOneB.calculate - SubjectGUID = 16dedf70-ae42-43ea-a30e-9f15e1 - identifier = fraab 2/28/2012 13:17:00 CalculationOneB.calculate - Before getting GPS observations - Memory [MB] used:22 free:77 total:100 max:1979 2/28/2012 13:17:05 CalculationOneB.calculate - processing GPS dataset item:10000 2/28/2012 13:17:06 CalculationOneB.calculate - Number of GPS observations = 16093 2/28/2012 13:17:06 CalculationOneB.calculate - After getting GPS observations - Memory [MB] used:106 free:60 total:166 max:1979

GPS Processing
Logs the epoch; number of first, last, and lone fixes. If satellite information is available, logs the number of indoor and outdoor fixes. Logs number of fixes judged invalid and removed by the filters.

2/28/2012 13:17:06 GPSprocessing.process - Version 4.0.0 09 Feb 2012 2/28/2012 13:17:06 GPSprocessing.getEpoch -- Epoch calculated as: 15 2/28/2012 13:17:06 GPSprocessing.preProcess - First Fixes:28 Last Fixes:28 Lone Fixes:0 Raw Fixes:16037 Total:16093 2/28/2012 13:17:07 GPSprocessing.markOutdoors - Outdoors based on SNR:7199 Based on sat_ratio:0 2/28/2012 13:17:07 GPSprocessing.markOutdoors - Indoors based on SNR:8894 Based on sat_ratio:0 2/28/2012 13:17:07 WARNING: GPSprocessing.filter - Max distance of 5625 at 2011-07-28 13:16:52.0 2/28/2012 13:17:07 GPSprocessing.process - After filtering - Processed: 16093 Filtered Speed: 20 ElevationDelta: 0 MaxDistance:1 MaxAcceleration:0 BackForth:4020 LoneFix:0 Invalid Points:4041 25% 2/28/2012 13:17:07 GPSprocessing.process - After filtering - Points remaining:12053

GPS - initial trip detection
Trip detection is a multiple pass process. Starts of trips are marked when a person moves the Min Distance in one minute (in this case, 34 meters). End of trips are marked when a person exceeds the Max Pause time or a loss of signal (LOS) occurs After trips are marked, the number of points in each classification is logged..

2/28/2012 13:17:07 GPSprocessing.detectTrips - Interval = 60 2/28/2012 13:17:07 GPSprocessing.detectTrips - Min Distance per minute (meters) = 34 2/28/2012 13:17:07 GPSprocessing.detectTrips - Max Distance per minute (meters) = 2166 2/28/2012 13:17:07 Trip start:2011-07-26 13:46:15.0 end:2011-07-26 14:23:45.0 - Max Pause exceeded while paused for 315 secs 2/28/2012 13:17:07 Trip start:2011-07-26 14:29:45.0 end:2011-07-26 15:33:07.0 - Max Pause exceeded while paused for 315 secs 2/28/2012 13:17:07 Trip start:2011-07-27 12:29:12.0 end:2011-07-27 12:40:22.0 - LOS while moving 2/28/2012 13:17:07 Trip start:2011-07-27 17:18:46.0 end:2011-07-27 18:04:02.0 - Max Pause exceeded while paused for 315 secs 2/28/2012 13:17:07 Trip start:2011-07-27 18:33:02.0 end:2011-07-27 18:35:47.0 - LOS while paused 2/28/2012 13:17:07 Trip start:2011-07-27 21:36:39.0 end:2011-07-27 22:01:03.0 - LOS while paused ............ 2/28/2012 13:17:07 GPSprocessing.detectTrips - Starts:80 Ends:80 Pauses:942 Mids:7247 Stationary:888

GPS - trim starting and ending points
In pass two, stationary

2/28/2012 13:17:07 GPSprocessing.trimTrips -- Removed trip: 2011-07-26 16:04:59 - 2011-07-26 16:05:59 2/28/2012 13:17:07 GPSprocessing.trimTrips -- Removed trip: 2011-07-28 14:45:59 - 2011-07-28 14:46:44 2/28/2012 13:17:07 GPSprocessing.trimTrips -- Removed trip: 2011-08-01 23:15:24 - 2011-08-01 23:16:09 2/28/2012 13:17:07 GPSprocessing.trimTrips -- Removed trip: 2011-08-03 11:04:20 - 2011-08-03 11:05:05

GPS - detect locations
Points marked as first fixes, last fixes, trip end points, start points and optionally pause points are initially considered locations. Duplicate locations (those with overlapping radius) are removed.

2/28/2012 13:17:07 GPSprocessing.clusterByFix - Finding track points with duration > 300 2/28/2012 13:17:07 GPSprocessing.clusterByFix - Including pause points as locations. 2/28/2012 13:17:07 GPSprocessing.clusterByFix - new locations initially detected:828 2/28/2012 13:17:23 GPSprocessing.removeDuplicateLocations - purging duplicate locations... 2/28/2012 13:17:23 GPSprocessing.removeDuplicateLocations - Duplicate locations removed:720 2/28/2012 13:17:23 GPSprocessing.removeDuplicateLocations - Number of locations returned:108 2/28/2012 13:17:23 GPSprocessing.addLocations - total number of common locations:108

GPS - reconsider trips based on locations
Once locations are detected, trips are reconsider. Trips can be reject if they do not meet the specified criteria: trip duration too short, trip length too short, trip occurred N percentage indoors.

2/28/2012 13:17:25 GPSprocessing.reconsiderTrips - min duration:180 min length:100 2/28/2012 13:17:25 Removed trip start:2011-07-26 13:47:15.0 end:2011-07-26 13:47:30.0 - duration 0 was too short 2/28/2012 13:17:25 Trip start:2011-07-26 14:30:45.0 Points indoors:144 outdoors:0 2/28/2012 13:17:25 Removed trip start:2011-07-26 14:30:45.0 end:2011-07-26 15:19:29.0 - occurred 100% indoors - max allowed is90% 2/28/2012 13:17:25 Trip start:2011-07-26 16:11:02.0 Points indoors:39 outdoors:0 2/28/2012 13:17:25 Removed trip start:2011-07-26 16:11:02.0 end:2011-07-26 16:23:20.0 - occurred 100% indoors - max allowed is90% 2/28/2012 13:17:25 Removed trip start:2011-07-26 16:45:46.0 end:2011-07-26 16:48:11.0 - duration 0 was too short 2/28/2012 13:17:25 Trip start:2011-07-26 17:37:51.0 Points indoors:1 outdoors:158 2/28/2012 13:17:25 Trip start:2011-07-26 18:31:51.0 Points indoors:7 outdoors:47 2/28/2012 13:17:25 Removed trip start:2011-07-27 18:33:47.0 end:2011-07-27 18:34:47.0 - duration 45 was too short 2/28/2012 13:17:25 Trip start:2011-07-27 21:37:24.0 Points indoors:16 outdoors:58 ..... 2/28/2012 13:17:25 GPSprocessing.reconsiderTrips - Number of trips removed: 34 Trips remaining:42

GPS - break trips into segments and look for changes in mode of transportation
The remaining trips are divided into segments of N meters. For each segment, the mode of transportation is estimated based on speed cutoffs. If the a mode change is notice of N contiguous segments, then the trips is split into separate trips.

2/28/2012 13:17:25 GPSprocessing.segmentTrip - Trip:1 Segment:1 Start:2011-07-26 17:37:51 End:2011-07-26 17:51:06 Mode:1 2/28/2012 13:17:25 Size:52 Index:46 Speed:6 Zeros:1 2/28/2012 13:17:25 [836,888] Mode:1 Certain:true Dist:1043 Dur:810 2/28/2012 13:17:25 GPSprocessing.segmentTrip - Trip:1 Segment:2 Start:2011-07-26 17:51:21 End:2011-07-26 17:58:36 Mode:1 2/28/2012 13:17:25 Size:27 Index:24 Speed:6 Zeros:3 2/28/2012 13:17:25 [889,918] Mode:1 Certain:true Dist:581 Dur:450 2/28/2012 13:17:25 GPSprocessing.segmentTrip - Trip:1 Segment:3 Start:2011-07-26 17:58:51 End:2011-07-26 18:03:36 Mode:3 2/28/2012 13:17:25 Size:18 Index:16 Speed:54 Zeros:2 2/28/2012 13:17:25 [919,938] Mode:3 Certain:true Dist:1875 Dur:300 2/28/2012 13:17:25 GPSprocessing.segmentTrip - Trip:1 Segment:4 Start:2011-07-26 18:03:51 End:2011-07-26 18:10:36 Mode:3 2/28/2012 13:17:25 Size:22 Index:19 Speed:55 Zeros:3 2/28/2012 13:17:25 [939,963] Mode:3 Certain:true Dist:3547 Dur:420 2/28/2012 13:17:25 GPSprocessing.segmentTrip - Trip:1 Segment:5 Start:2011-07-26 18:10:51 End:2011-07-26 18:16:06 Mode:3 2/28/2012 13:17:25 Size:19 Index:17 Speed:43 Zeros:2 2/28/2012 13:17:25 [964,984] Mode:3 Certain:true Dist:1913 Dur:330 2/28/2012 13:17:25 GPSprocessing.segmentTrip - Trip:1 Segment:6 Start:2011-07-26 18:16:21 End:2011-07-26 18:18:51 Mode:2 2/28/2012 13:17:25 Size:4 Index:3 Speed:16 Zeros:2 2/28/2012 13:17:25 [985,990] Mode:2 Certain:true Dist:116 Dur:165 2/28/2012 13:17:25 GPSprocessing.segmentTrip - Trip:1 Segment:7 Start:2011-07-26 18:19:06 End:2011-07-26 18:20:06 Mode:1 2/28/2012 13:17:25 Size:5 Index:4 Speed:5 Zeros:0 2/28/2012 13:17:25 [991,995] Mode:1 Certain:false Dist:62 Dur:75 2/28/2012 13:17:25 GPSprocessing.classifyAndNumberTrips -- odd mode change - leg =6 2/28/2012 13:17:25 Checking for mode changes from 2011-07-26 17:37:51 to 2011-07-26 18:20:06 2/28/2012 13:17:25 GPSProcessingR4.classifyAndNumberTrips - spliting trip at:2011-07-26 17:58:51 Previous mode:1 Current Mode:3 2/28/2012 13:17:25 GPSProcessingR4.classifyAndNumberTrips - spliting trip at:2011-07-26 18:16:21 Previous mode:3 Current Mode:2 2/28/2012 13:17:25 GPSProcessingR4.classifyAndNumberTrips - spliting trip at:2011-07-26 18:19:06 Previous mode:2 Current Mode:1 .... (only one trip shown) ......

GPS - reconsider new trips created from segments
Trips are again reconsidered.

2/28/2012 13:17:26 GPSprocessing.process - Reconsider trips after classification 2/28/2012 13:17:26 GPSprocessing.reconsiderTrips - min duration:180 min length:100 2/28/2012 13:17:26 Trip start:2011-07-26 17:37:51.0 Points indoors:0 outdoors:82 2/28/2012 13:17:26 Trip start:2011-07-27 08:42:47.0 Points indoors:0 outdoors:14 2/28/2012 13:17:26 Trip start:2011-07-27 09:08:02.0 Points indoors:6 outdoors:111 2/28/2012 13:17:26 Removed trip start:2011-07-28 18:13:00.0 end:2011-07-28 18:14:01.0 - duration 46 was too short 2/28/2012 13:17:26 Trip start:2011-07-29 08:33:26.0 Points indoors:14 outdoors:116 2/28/2012 13:17:26 Trip start:2011-07-29 09:09:59.0 Points indoors:197 outdoors:0 2/28/2012 13:17:26 Removed trip start:2011-07-29 09:09:59.0 end:2011-07-29 10:07:51.0 - occurred 100% indoors - max allowed is90% 2/28/2012 13:17:26 Trip start:2011-07-29 18:23:27.0 Points indoors:0 outdoors:103 2/28/2012 13:17:26 Trip start:2011-07-31 16:32:14.0 Points indoors:14 outdoors:54 ...... 2/28/2012 13:17:26 GPSprocessing.reconsiderTrips - Number of trips removed: 22 Trips remaining:66

GPS - Align to desired interval
Points are aligned to the desired interval. The number of points removed and remaining after alignment are logged.

2/28/2012 13:17:26 GPSprocessing.alignToInterval - Interval (seconds):60 points dropped:8817 remaining:3237 2/28/2012 13:17:26 CalculationOneB.calculate: processed GPS vector - size = 3237 2/28/2012 13:17:26 CalculationOneB.calculate - After GPS Processing - Memory [MB] used:136 free:29 total:166 max:1979

Activity Data Processing
For each subject, logs the number of activity records retrieved from the database.

2/28/2012 13:17:33 CalculationOneB.getActivityDataSet - fetched activity data - size = 91805 2/28/2012 13:17:35 CalculationOneB.getActivityDataSet - Number of activity observations = 91805 2/28/2012 13:17:35 CalculationOneB.getActivityDataSet - After getting activity observations - Memory [MB] used:286 free:46 total:332 max:1979

Heart Rate Processing
If heart rate data was available, any errors generated during heart rate processing would be reported here.

2/28/2012 13:17:35 HeartRateProcessing.process - Version 2.0.0a 27 Sep 2011 2/28/2012 13:17:35 HeartRateProcessing.process - no heart rate data to process.

Accelerometer Processing
Logs the number of observations removed after aligning to the desired interval; the number of non-wearing periods detected and the number of activity and sedentary bouts detected.

2/28/2012 13:17:35 AccelerometerProcessing.process - Version 4.0.0 13 Jan 2012 2/28/2012 13:17:35 AccelerometerProcessing.process - Original epoch (in seconds) = 30 2/28/2012 13:17:35 AccelerometerProcessing.alignToIntervalVersion2 - observations dropped:45902 2/28/2012 13:17:35 AccelerometerProcessing.process - Epoch after alignment = 60 2/28/2012 13:17:35 AccelerometerProcessing.process - Detecting not-wearing after 30 minutes. 2/28/2012 13:17:35 AccelerometerProcessing.process - 129 Not-wearing periods detected. 2/28/2012 13:17:35 AccelerometerProcessing.detectBouts - duration (min):5 tolerance (min):2 2/28/2012 13:17:35 AccelerometerProcessing.detectBouts - cutoffs (per minute):1953.0 - 9999.0 2/28/2012 13:17:35 AccelerometerProcessing.detectBouts - cutoffs (per epoch):1953.0 - 9999.0 2/28/2012 13:17:35 AccelerometerProcessing.detectBouts - Activity bouts detected:59 2/28/2012 13:17:35 WARNING: AccelerometerProcessing.process -- Sedentary bout duration of 30 minutes >= non-wearing minutes of 30 2/28/2012 13:17:35 AccelerometerProcessing.detectBouts - duration (min):30 tolerance (min):1 2/28/2012 13:17:35 AccelerometerProcessing.detectBouts - cutoffs (per minute):0.0 - 100.0 2/28/2012 13:17:35 AccelerometerProcessing.detectBouts - cutoffs (per epoch):0.0 - 100.0 2/28/2012 13:17:35 AccelerometerProcessing.detectBouts - Sedentary bouts detected:84

Lux Processing
If lux data was available (typically with Actigraph devices), any errors generated during lux processing would be reported here.

2/28/2012 13:17:35 LuxProcessing.process - Version 1.0.0 12 Jan 2012 2/28/2012 13:17:35 LuxProcessing.process - No lux data present.

Energy Expenditure (EE) Processing
If an EE formula was specified in the parameters, any errors generated during EE processing would be reported here.

2/28/2012 13:17:35 EEprocessing.process - Version 1.3.0 12 Jan 2012 2/28/2012 13:17:35 EEprocessing - no EE calculation selected.

Merge Processing
Logs the number of GPS and activity items to be merged, the earliest and latest entry of each.

2/28/2012 13:17:35 CalculationOneB.calculate: processed activity vector - size = 45903 2/28/2012 13:17:35 CalculationOneB.calculate - startingMerge - interval = 60 Number of GPS items = 3237 Number of activity items = 45903 2/28/2012 13:17:35 CalculationOneB.calculate - Before merge - Memory [MB] used:289 free:43 total:332 max:1979 2/28/2012 13:17:35 MergeDataSets.merge - Version 4.0.0 17 Jan 2012 2/28/2012 13:17:35 MergeDataSets.merge - GPS earliest:2011-07-26 13:17:00.0 - latest:2011-08-04 12:01:00.0 2/28/2012 13:17:35 MergeDataSets.merge - Activity earliest:2010-08-16 10:03:00.0 - latest:2011-08-02 10:55:00.0 2/28/2012 13:17:35 MergeDataSets.merge - merging Activity data to GPS trackpoints. 2/28/2012 13:17:35 MergeDataSets.merge - inserting missing GPS track points. 2/28/2012 13:17:35 MergeDataSets.merge - Starting timestamp = 2011-07-26 13:17:00.0 2/28/2012 13:17:35 MergeDataSets.merge - ending timestamp = 2011-08-04 12:01:00.0 2/28/2012 13:17:38 MergeDataSets.merge - finished - vpd size = 12885 2/28/2012 13:17:38 CalculationOneB.calculate - merged datasets - size = 12885

Merge - Calculate mode of transportation
Mode of transportation is reconsidered based on activity levels. Any trips modified are logged here.

2/28/2012 13:17:38 MergeDataSets.calculateModeOfTransportation 2/28/2012 13:17:38 Trips processed:0 2/28/2012 13:17:38 Trips modified:0 Points modified:0

Merge - Mark events
If events are to be marked, any error are reported here.

2/28/2012 13:17:38 MergeDataSets.markEvents - no events specified to mark. 2/28/2012 13:17:38 CalculationOneB.calculate - After merge - Memory [MB] used:112 free:220 total:332 max:1979

Generating the Result Set
Once the data streams are merge, a result set is generated and stored. Progress is reported every block of 10,000 rows.

2/28/2012 13:17:43 CalculationOneB.createResultSet - Processed block:9999 2/28/2012 13:17:44 CalculationOneB.createResultSet - Processed block:12884 2/28/2012 13:17:44 CalculationOneB.createResultSet - Percent complete:99 Total number of output rows so far:12885 2/28/2012 13:17:44 CalculationOneB.calculate - After updating result set - Memory [MB] used:143 free:189 total:332 max:1979 2/28/2012 13:17:44 CalculationOne.calculate - Successful completion - number of output rows = 12885 2/28/2012 13:17:44 CalculationOneB.calculate - After GC - Memory [MB] used:28 free:284 total:312 max:1979

Fatal Errors that Halt Calculations
If an error is reported in the result set listing, details about the error can be found in the log file. Reading the log file will indicate where in the process chain the error occurred.

In the log below, a programming error occurred in the GPS processing while classifying trip legs. An "array index out of bounds exception" was triggered and the execution of the calculation halted. Report such programming errors to PALMS staff. (The error in this case has since been fixed.)

2/10/2012 8:33:11 GPSprocessing.classifyTripLeg - Trip:22 Leg:1 Start:2008-11-09 09:34:23 AvgSpeed:11.666666666666666 MaxSpeed:27 Mode:bicycle 2/10/2012 8:33:11 GPSprocessing.classifyTripLeg - Trip:22 Leg:2 Start:2008-11-09 09:45:56 AvgSpeed:0.0 MaxSpeed:0 Mode:pedestrian 2/10/2012 8:33:11 GPSprocessing.processPausePoints - spliting trip 22 previous mode: bicycle current mode: pedestrian 2/10/2012 8:33:11 ERROR: GPSprocessing.classifyAndNumberTrips -- programming error 2/10/2012 8:33:11 ERROR: Failed: ExecuteCalculation.execute (java.lang.ArrayIndexOutOfBoundsException) at java.util.Vector.get(Unknown Source): [context: credentialToken: null, study: 87b7a919-9fd7-4ad6-88c9-6a3e1d, dispatchID: edbcd282-2a8f-485f-86d7-cfc20a] -1

Sometimes the error is complex, resulting in multiple exceptions. Report such errors to the PALMS staff for resolution. Send an email to palms@ucsd.edu providing the name of the study and the name of the result set. Do not delete the result set.

7/22/2011 6:51:55 CalculationOneB.calculate - After merge - Memory [MB] used:118 free:652 total:770 max:4949 7/22/2011 6:51:55 ERROR: Failed: ExecuteCalculation.execute (java.lang.Exception) at org.paceproject.palms.service.study.service.dataset.data.data.DatasetDataRepositoryLocal.addData(DatasetDataRepositoryLocal.java:56): [context: credentialToken: null, study: d503f48a-d793-4650-abd5-def833, dispatchID: 8bd91645-3b85-4ed6-aad7-6057f3] DatasetRepositoryLocal.addData (java.lang.Exception) at org.paceproject.palms.service.study.service.dataset.data.data.DatasetDataRepositoryLocal.addData(DatasetDataRepositoryLocal.java:54): [context: d503f48a-d793-4650-abd5-def833] DatasetRepository.addData (java.lang.Exception) at org.paceproject.palms.service.study.service.result.repository.datasetAdapter.DatasetResultRepositoryLocal.addData(DatasetResultRepositoryLocal.java:63): [context: Study: d503f48a-d793-4650-abd5-def833, qualifierKey: result://0f315fda-08c0-49b1-9c52-889433, rowList: rowCount: 10000] DatasetResultRepositoryLocal.addData (java.lang.Exception) at org.paceproject.palms.service.study.service.result.repository.datasetAdapter.DatasetResultRepositoryLocal.addData(DatasetResultRepositoryLocal.java:61): [context: d503f48a-d793-4650-abd5-def833] DatasetResultRepository.addData (java.lang.Exception) at org.paceproject.palms.service.study.service.result.ResultSetUtils.getResultSetMetadata(ResultSetUtils.java:23): [context: Study: d503f48a-d793-4650-abd5-def833, qualifierKey: result://0f315fda-08c0-49b1-9c52-889433, rowList: rowCount: 10000] Could not find resultID 0f315fda-08c0-49b1-9c52-889433