Heap Memory Profile Probe
Contents
Heap Memory Profile Probe: hmp.ual
(Since 4.5.0).
The hmp.ual predefined probe profiles the use of heap memory within an application program. The probe records the number, size, and time taken for allocations and deallocations from and to the heap. The profiling information is reported periodically in snapshots and in a final snapshot at the program termination.
Heap profiling allows you to determine how the heap is being used in your application. The heap profile information can be used to locate "hot spots" of heap usage in your application on which to focus your attention when trying to improve your program's performance. This probe focuses on overall usage not on specific allocations and deallocations.
See memstat.ual, memleak.ual and memwatch.ual for other approaches to heap analysis.
Usage
This probe is applied at run time using aprobe as described under Profile UAL Parameters below. Heap profiling data will be collected for the standard memory functions: malloc, calloc, realloc, and free. You would need to modify this probe to collect information from custom allocation functions.
The heap profile information is collected in memory and periodically logged in snapshots logged to the APD file for later processing by apformat. At format time a report is generated for each snapshot and an overall summary for the whole program which details the number and duration of allocations and deallocation of objects of different sizes. The data is tabulated and displayed in histograms. The reports are designed to allow you to identify areas of heavy heap usage based on object sizes rather than specific objects. This analysis may be followed up by custom probes to discover where the application is allocating objects of a specific size, for example.
The default parameters provide good initial coverage of heap object sizes by defining bucket sizes that increase by powers of two. Object smaller than the smallest bucket size are tallied in the the smallest bucket and object larger than the largest bucket size are tallied in the largest bucket. You can focus on specific object size by specifying a starting bucket size and the number of buckets to use with linearly increasing sizes.
You can also track the lifetimes of objects by using the -l option. This will report on the lifetime of objects by size, and produce additional tabular and histogram reports.
NOTE: Prior to Aprobe 4.5.4, hmp.ual was not delivered compiled on Linux 32-bit systems. You will have to compile it yourself by copying the source, hmp.apc, from $APROBE/probes to a local directory to compile it with:
apc -v -g hmp.apc -linker “-lpthreads -lrt”
Profile UAL Parameters
hmp.ual is specified on the aprobe command line or in an APO file as described in Command Line. The specific options are:
aprobe -u hmp.ual [-p "param-list"] your_program
where param_list may include:
- -i InitTime
- num secs before starting snapshots [SnapTime]
- -w WaitTime
- wait WaitTime secs before tracking allocations [0]
- -s SnapTime
- num secs between snapshots after InitTime [30]
- -r
- reset statistics after each snapshot
- -x
- collect CPU times in addtion to wall times
- -y
- Use MONOTONIC clock instead of CPU clock (implies -x)
- -b NBuckets
- number of buckets : default 16
- -c BucketSize
- size in bytes of each bucket : default 0 (= doubling)
- -d BucketStart
- first bucket size in bytes : default 32
- -l
- track object lifetimes : default off
- -t NTimeBuckets
- number of time buckets : default 10
- -u TimeBucketSize
- size in seconds of each time bucket : default 0 (= doubling)
- -v TimeBucketStart
- first time bucket time in seconds : default 1
Heap Memory Profile API
Users can control the behavior of the heap memory profile probe by calls from within their own probes. The API is defined by [../include/hmp.h $APROBE/include/hmp.h]. The functions exported by hmp.ual are:
- ap_Hmp_DoSnapshot
Takes a snapshot of heap memory profile data.
See Snapshots for more information and an example.
Heap Memory Profile Demand Actions
You can control hmp.ual using demand.ual and apdemand.
Include demand.ual on the Aprobe command line:
aprobe -u hmp -u demand myapp.exe
then use apdemand to send actions:
apdemand hmp snapshot
hmp.ual responds to the following actions:
- hmp snapshot
Note that all actions containing the action string will be triggered.
Heap Memory Profile Performance Issues
See Performance_Issues for a general discussion of factors that affect performance.
You can use the InitTime and WaitTime options to control when heap memory profiling is performed. This can reduce the overhead during application start-up when many tables and other data structures are populated by allocations from the heap.
While snapshots are reasonable quick, you can use the SnapTime option to control how often, if at all, periodic snapshots are taken.
Heap Memory Profile Report
The reports generated by running apformat vary considerably depending upon the options chosen as specified above. The default looks like the example below:
Heap Memory Profile Probe 4.5.0 (181025)
Copyright 1993-2018 OC Systems, Inc. All rights reserved.
For support/questions send mail to support@ocsystems.com.
PID: 17171 - Summary of options
Program start: Thu Oct 25 14:47:02.828433 2018
Options:
WaitTime: 0
InitTime: 60
SnapTime: 60
Buckets: 16
Bucket Size: 0
Bucket Start: 32
TimeBuckets: 10
Time Bucket Size: 0
Time Bucket Start: 1
TrackLifetime: 0
ResetStats: 0
CPUTime: 0
Monotonic: 0
SnapshotSig: 0
Heap Memory Profile Probe 4.5.0 (181025)
Copyright 1993-2018 OC Systems, Inc. All rights reserved.
For support/questions send mail to support@ocsystems.com.
PID: 17171 - Summary of snapshot #1 ("Final Snapshot")
Program start: Thu Oct 25 14:47:02.828433 2018
Snapshot time: Thu Oct 25 14:48:32.830581 2018
Buckets: 16
Bucket Size: 0
Bucket Start: 32
TimeBuckets: 10
Time Bucket Size: 0
Time Bucket Start: 1
Overall:
MaxOutstanding: 13
BytesAllocated: 99,439
BytesFreed: 82,710
NumAllocs: 27
AvgAllocSize: 3,682
MaxAllocSize: 9,783
TotalAllocTime: 0.0001730000
AvgAllocTime: 0.0000064074
MaxAllocTime: 0.0000460000
MaxAllocTimeSize: 5,038
NumReallocs: 0
MaxReallocSize: 0
TotalReallocTime: 0.0000000000
AvgReallocTime: 0.0000000000
MaxReallocTime: 0.0000000000
MaxReallocTimeSize: 0
NumFrees: 20
AvgFreeSize: 4,135
MaxFreeSize: 9,793
TotalFreeTime: 0.0001030000
AvgFreeTime: 0.0000051500
MaxFreeTime: 0.0000190000
MaxFreeTimeSize: 0
Bucket:
Size: 0 .. 32
MaxOutstanding: 0
BytesAllocated: 0
BytesFreed: 0
NumAllocs: 0
AvgAllocSize: 0
MaxAllocSize: 0
TotalAllocTime: 0.0000000000
AvgAllocTime: 0.0000000000
MaxAllocTime: 0.0000000000
MaxAllocTimeSize: 0
NumReallocs: 0
MaxReallocSize: 0
TotalReallocTime: 0.0000000000
AvgReallocTime: 0.0000000000
MaxReallocTime: 0.0000000000
MaxReallocTimeSize: 0
NumFrees: 0
AvgFreeSize: 0
MaxFreeSize: 0
TotalFreeTime: 0.0000000000
AvgFreeTime: 0.0000000000
MaxFreeTime: 0.0000000000
MaxFreeTimeSize: 0
Bucket:
Size: 33 .. 64
MaxOutstanding: 0
BytesAllocated: 0
BytesFreed: 0
NumAllocs: 0
AvgAllocSize: 0
MaxAllocSize: 0
TotalAllocTime: 0.0000000000
AvgAllocTime: 0.0000000000
MaxAllocTime: 0.0000000000
MaxAllocTimeSize: 0
NumReallocs: 0
MaxReallocSize: 0
TotalReallocTime: 0.0000000000
AvgReallocTime: 0.0000000000
MaxReallocTime: 0.0000000000
MaxReallocTimeSize: 0
NumFrees: 0
AvgFreeSize: 0
MaxFreeSize: 0
TotalFreeTime: 0.0000000000
AvgFreeTime: 0.0000000000
MaxFreeTime: 0.0000000000
MaxFreeTimeSize: 0
Bucket:
Size: 65 .. 128
MaxOutstanding: 0
BytesAllocated: 0
BytesFreed: 0
NumAllocs: 0
AvgAllocSize: 0
MaxAllocSize: 0
TotalAllocTime: 0.0000000000
AvgAllocTime: 0.0000000000
MaxAllocTime: 0.0000000000
MaxAllocTimeSize: 0
NumReallocs: 0
MaxReallocSize: 0
TotalReallocTime: 0.0000000000
AvgReallocTime: 0.0000000000
MaxReallocTime: 0.0000000000
MaxReallocTimeSize: 0
NumFrees: 0
AvgFreeSize: 0
MaxFreeSize: 0
TotalFreeTime: 0.0000000000
AvgFreeTime: 0.0000000000
MaxFreeTime: 0.0000000000
MaxFreeTimeSize: 0
Bucket:
Size: 129 .. 256
MaxOutstanding: 0
BytesAllocated: 0
BytesFreed: 0
NumAllocs: 0
AvgAllocSize: 0
MaxAllocSize: 0
TotalAllocTime: 0.0000000000
AvgAllocTime: 0.0000000000
MaxAllocTime: 0.0000000000
MaxAllocTimeSize: 0
NumReallocs: 0
MaxReallocSize: 0
TotalReallocTime: 0.0000000000
AvgReallocTime: 0.0000000000
MaxReallocTime: 0.0000000000
MaxReallocTimeSize: 0
NumFrees: 0
AvgFreeSize: 0
MaxFreeSize: 0
TotalFreeTime: 0.0000000000
AvgFreeTime: 0.0000000000
MaxFreeTime: 0.0000000000
MaxFreeTimeSize: 0
Bucket:
Size: 257 .. 512
MaxOutstanding: 6
BytesAllocated: 1,851
BytesFreed: 714
NumAllocs: 6
AvgAllocSize: 308
MaxAllocSize: 411
TotalAllocTime: 0.0000140000
AvgAllocTime: 0.0000023333
MaxAllocTime: 0.0000030000
MaxAllocTimeSize: 288
NumReallocs: 0
MaxReallocSize: 0
TotalReallocTime: 0.0000000000
AvgReallocTime: 0.0000000000
MaxReallocTime: 0.0000000000
MaxReallocTimeSize: 0
NumFrees: 2
AvgFreeSize: 357
MaxFreeSize: 417
TotalFreeTime: 0.0000060000
AvgFreeTime: 0.0000030000
MaxFreeTime: 0.0000050000
MaxFreeTimeSize: 0
Bucket:
Size: 513 .. 1,024
MaxOutstanding: 0
BytesAllocated: 0
BytesFreed: 0
NumAllocs: 0
AvgAllocSize: 0
MaxAllocSize: 0
TotalAllocTime: 0.0000000000
AvgAllocTime: 0.0000000000
MaxAllocTime: 0.0000000000
MaxAllocTimeSize: 0
NumReallocs: 0
MaxReallocSize: 0
TotalReallocTime: 0.0000000000
AvgReallocTime: 0.0000000000
MaxReallocTime: 0.0000000000
MaxReallocTimeSize: 0
NumFrees: 0
AvgFreeSize: 0
MaxFreeSize: 0
TotalFreeTime: 0.0000000000
AvgFreeTime: 0.0000000000
MaxFreeTime: 0.0000000000
MaxFreeTimeSize: 0
Bucket:
Size: 1,025 .. 2,048
MaxOutstanding: 1
BytesAllocated: 4,061
BytesFreed: 4,090
NumAllocs: 3
AvgAllocSize: 1,353
MaxAllocSize: 1,945
TotalAllocTime: 0.0000090000
AvgAllocTime: 0.0000030000
MaxAllocTime: 0.0000040000
MaxAllocTimeSize: 1,031
NumReallocs: 0
MaxReallocSize: 0
TotalReallocTime: 0.0000000000
AvgReallocTime: 0.0000000000
MaxReallocTime: 0.0000000000
MaxReallocTimeSize: 0
NumFrees: 3
AvgFreeSize: 1,363
MaxFreeSize: 1,953
TotalFreeTime: 0.0000160000
AvgFreeTime: 0.0000053333
MaxFreeTime: 0.0000060000
MaxFreeTimeSize: 0
Bucket:
Size: 2,049 .. 4,096
MaxOutstanding: 4
BytesAllocated: 22,375
BytesFreed: 16,396
NumAllocs: 7
AvgAllocSize: 3,196
MaxAllocSize: 3,857
TotalAllocTime: 0.0000260000
AvgAllocTime: 0.0000037143
MaxAllocTime: 0.0000060000
MaxAllocTimeSize: 3,555
NumReallocs: 0
MaxReallocSize: 0
TotalReallocTime: 0.0000000000
AvgReallocTime: 0.0000000000
MaxReallocTime: 0.0000000000
MaxReallocTimeSize: 0
NumFrees: 5
AvgFreeSize: 3,279
MaxFreeSize: 3,801
TotalFreeTime: 0.0000370000
AvgFreeTime: 0.0000074000
MaxFreeTime: 0.0000190000
MaxFreeTimeSize: 0
Bucket:
Size: 4,097 .. 8,192
MaxOutstanding: 5
BytesAllocated: 42,419
BytesFreed: 42,492
NumAllocs: 8
AvgAllocSize: 5,302
MaxAllocSize: 7,081
TotalAllocTime: 0.0001070000
AvgAllocTime: 0.0000133750
MaxAllocTime: 0.0000460000
MaxAllocTimeSize: 5,038
NumReallocs: 0
MaxReallocSize: 0
TotalReallocTime: 0.0000000000
AvgReallocTime: 0.0000000000
MaxReallocTime: 0.0000000000
MaxReallocTimeSize: 0
NumFrees: 8
AvgFreeSize: 5,311
MaxFreeSize: 7,089
TotalFreeTime: 0.0000340000
AvgFreeTime: 0.0000042500
MaxFreeTime: 0.0000050000
MaxFreeTimeSize: 0
Bucket:
Size: 8,193 .. 16,384
MaxOutstanding: 2
BytesAllocated: 28,733
BytesFreed: 19,018
NumAllocs: 3
AvgAllocSize: 9,577
MaxAllocSize: 9,783
TotalAllocTime: 0.0000170000
AvgAllocTime: 0.0000056667
MaxAllocTime: 0.0000080000
MaxAllocTimeSize: 9,783
NumReallocs: 0
MaxReallocSize: 0
TotalReallocTime: 0.0000000000
AvgReallocTime: 0.0000000000
MaxReallocTime: 0.0000000000
MaxReallocTimeSize: 0
NumFrees: 2
AvgFreeSize: 9,509
MaxFreeSize: 9,793
TotalFreeTime: 0.0000100000
AvgFreeTime: 0.0000050000
MaxFreeTime: 0.0000060000
MaxFreeTimeSize: 0
Bucket:
Size: 16,385 .. 32,768
MaxOutstanding: 0
BytesAllocated: 0
BytesFreed: 0
NumAllocs: 0
AvgAllocSize: 0
MaxAllocSize: 0
TotalAllocTime: 0.0000000000
AvgAllocTime: 0.0000000000
MaxAllocTime: 0.0000000000
MaxAllocTimeSize: 0
NumReallocs: 0
MaxReallocSize: 0
TotalReallocTime: 0.0000000000
AvgReallocTime: 0.0000000000
MaxReallocTime: 0.0000000000
MaxReallocTimeSize: 0
NumFrees: 0
AvgFreeSize: 0
MaxFreeSize: 0
TotalFreeTime: 0.0000000000
AvgFreeTime: 0.0000000000
MaxFreeTime: 0.0000000000
MaxFreeTimeSize: 0
Bucket:
Size: 32,769 .. 65,536
MaxOutstanding: 0
BytesAllocated: 0
BytesFreed: 0
NumAllocs: 0
AvgAllocSize: 0
MaxAllocSize: 0
TotalAllocTime: 0.0000000000
AvgAllocTime: 0.0000000000
MaxAllocTime: 0.0000000000
MaxAllocTimeSize: 0
NumReallocs: 0
MaxReallocSize: 0
TotalReallocTime: 0.0000000000
AvgReallocTime: 0.0000000000
MaxReallocTime: 0.0000000000
MaxReallocTimeSize: 0
NumFrees: 0
AvgFreeSize: 0
MaxFreeSize: 0
TotalFreeTime: 0.0000000000
AvgFreeTime: 0.0000000000
MaxFreeTime: 0.0000000000
MaxFreeTimeSize: 0
Bucket:
Size: 65,537 .. 131,072
MaxOutstanding: 0
BytesAllocated: 0
BytesFreed: 0
NumAllocs: 0
AvgAllocSize: 0
MaxAllocSize: 0
TotalAllocTime: 0.0000000000
AvgAllocTime: 0.0000000000
MaxAllocTime: 0.0000000000
MaxAllocTimeSize: 0
NumReallocs: 0
MaxReallocSize: 0
TotalReallocTime: 0.0000000000
AvgReallocTime: 0.0000000000
MaxReallocTime: 0.0000000000
MaxReallocTimeSize: 0
NumFrees: 0
AvgFreeSize: 0
MaxFreeSize: 0
TotalFreeTime: 0.0000000000
AvgFreeTime: 0.0000000000
MaxFreeTime: 0.0000000000
MaxFreeTimeSize: 0
Bucket:
Size: 131,073 .. 262,144
MaxOutstanding: 0
BytesAllocated: 0
BytesFreed: 0
NumAllocs: 0
AvgAllocSize: 0
MaxAllocSize: 0
TotalAllocTime: 0.0000000000
AvgAllocTime: 0.0000000000
MaxAllocTime: 0.0000000000
MaxAllocTimeSize: 0
NumReallocs: 0
MaxReallocSize: 0
TotalReallocTime: 0.0000000000
AvgReallocTime: 0.0000000000
MaxReallocTime: 0.0000000000
MaxReallocTimeSize: 0
NumFrees: 0
AvgFreeSize: 0
MaxFreeSize: 0
TotalFreeTime: 0.0000000000
AvgFreeTime: 0.0000000000
MaxFreeTime: 0.0000000000
MaxFreeTimeSize: 0
Bucket:
Size: 262,145 .. 524,288
MaxOutstanding: 0
BytesAllocated: 0
BytesFreed: 0
NumAllocs: 0
AvgAllocSize: 0
MaxAllocSize: 0
TotalAllocTime: 0.0000000000
AvgAllocTime: 0.0000000000
MaxAllocTime: 0.0000000000
MaxAllocTimeSize: 0
NumReallocs: 0
MaxReallocSize: 0
TotalReallocTime: 0.0000000000
AvgReallocTime: 0.0000000000
MaxReallocTime: 0.0000000000
MaxReallocTimeSize: 0
NumFrees: 0
AvgFreeSize: 0
MaxFreeSize: 0
TotalFreeTime: 0.0000000000
AvgFreeTime: 0.0000000000
MaxFreeTime: 0.0000000000
MaxFreeTimeSize: 0
Bucket:
Size: 524,289 .. 2,147,483,647
MaxOutstanding: 0
BytesAllocated: 0
BytesFreed: 0
NumAllocs: 0
AvgAllocSize: 0
MaxAllocSize: 0
TotalAllocTime: 0.0000000000
AvgAllocTime: 0.0000000000
MaxAllocTime: 0.0000000000
MaxAllocTimeSize: 0
NumReallocs: 0
MaxReallocSize: 0
TotalReallocTime: 0.0000000000
AvgReallocTime: 0.0000000000
MaxReallocTime: 0.0000000000
MaxReallocTimeSize: 0
NumFrees: 0
AvgFreeSize: 0
MaxFreeSize: 0
TotalFreeTime: 0.0000000000
AvgFreeTime: 0.0000000000
MaxFreeTime: 0.0000000000
MaxFreeTimeSize: 0
Allocs Histogram:
0 .. 32 :
33 .. 64 :
65 .. 128 :
129 .. 256 :
257 .. 512 : ******
513 .. 1024 :
1025 .. 2048 : ***
2049 .. 4096 : *******
4097 .. 8192 : ********
8193 .. 16384 : ***
16385 .. 32768 :
32769 .. 65536 :
65537 .. 131072 :
131073 .. 262144 :
262145 .. 524288 :
524289 .. 2147483647 :
Reallocs Histogram:
0 .. 32 :
33 .. 64 :
65 .. 128 :
129 .. 256 :
257 .. 512 :
513 .. 1024 :
1025 .. 2048 :
2049 .. 4096 :
4097 .. 8192 :
8193 .. 16384 :
16385 .. 32768 :
32769 .. 65536 :
65537 .. 131072 :
131073 .. 262144 :
262145 .. 524288 :
524289 .. 2147483647 :
The report starts with a summary of the options used for the run.
Next comes a snapshot, in this case the final snapshot on program termination. The snapshot reports some information about the buckets used to summarize the data, and overall information for all object sizes for the snapshot. Next are summaries for each object size bucket of the snapshot. Following the bucket summaries there are histograms displaying the spread of object sizes recorded for the snapshot.
Note that allocation and reallocation data are tracked separately, because it is not possible to separate the deallocation time forth allocation time in a realloc() call. In practice this should not be a significant problem.
This is a final snapshot so the statistics cover the entire run. If there were periodic snapshots taken, the statistics for each snapshot might reset depending on the -r option.
In this particular example there are no glaring hot spots, but further investigation of object sizes between 2KB and 8KB might be warranted. In that case you might run with:
aprobe -u hmp -p "-b 8 -c 1024 -d 2048"
to track objects in 8 buckets starting at 2048 bytes and incrementing by 1024 bytes.
Heap Memory Profile Lifetime Report
When lifetime data is selected each size bucket section includes additional lifetime information like:
Bucket: Size: 2,049 .. 4,096 MaxOutstanding: 5 BytesAllocated: 13,908 BytesFreed: 9,866 NumAllocs: 5 AvgAllocSize: 2,781 MaxAllocSize: 4,087 TotalAllocTime: 0.0000190000 AvgAllocTime: 0.0000038000 MaxAllocTime: 0.0000090000 MaxAllocTimeSize: 4,087 NumReallocs: 0 MaxReallocSize: 0 TotalReallocTime: 0.0000000000 AvgReallocTime: 0.0000000000 MaxReallocTime: 0.0000000000 MaxReallocTimeSize: 0 NumFrees: 4 AvgFreeSize: 2,466 MaxFreeSize: 2,617 TotalFreeTime: 0.0000200000 AvgFreeTime: 0.0000050000 MaxFreeTime: 0.0000060000 MaxFreeTimeSize: 0 Time Bucket: Secs: 0 .. 1 Count: 0 Time Bucket: Secs: 2 .. 2 Count: 0 Time Bucket: Secs: 3 .. 4 Count: 0 Time Bucket: Secs: 5 .. 8 Count: 0 Time Bucket: Secs: 9 .. 16 Count: 0 Time Bucket: Secs: 17 .. 32 Count: 1 Time Bucket: Secs: 33 .. 64 Count: 3 Time Bucket: Secs: 65 .. 128 Count: 0 Time Bucket: Secs: 129 .. 256 Count: 0 Time Bucket: Secs: 257 .. 2,147,483,647 Count: 0 Time Histogram: 0 .. 1 : 2 .. 2 : 3 .. 4 : 5 .. 8 : 9 .. 16 : 17 .. 32 : * 33 .. 64 : *** 65 .. 128 : 129 .. 256 : 257 .. 2147483647 :
There are time buckets reported for seconds of duration, and a histogram of the spread of lifetime durations.