Confusing and suspicious PROFILER output [message #83243] |
Wed, 13 February 2013 21:06 |
Matt Francis
Messages: 94 Registered: May 2010
|
Member |
|
|
I am having trouble interpreting PROFILER output that I suspect is due to CALL_EXTERNAL.
I am doing Kalman Filtering over large data sets. The core function that computes the Kalman Gain is naturally using the bulk of the runtime, however it is being reported strangely. This function makes a few get calls to retrieve the matrices, does some matrix multiplication using the # operator, then call a routine ATLAS_INVERT which in turn uses CALL_EXTERNAL to use the ATLAS library LAPACK routines to invert the matrix. Here is the profiler output from these three routines:
NAME, COUNT, ONLY, TIME, , SYS
FILTER::KALMAN_GAIN, 18655, 1210.767071542437, 70.05589485168457, 0
ATLAS_INVERT, 18655, 1.371216606964101, 38.50398111343384, 0
CALL_EXTERNAL, 37310, 36.37221550941467, 36.37221550941467, 1
How can we make sense of this? The report for FILTER::KALMAN_GAIN seems screwy in that it takes less time for the routine + subroutines than the routine alone? Ignoring that issue, this implies that the matrix multiplication via the # operator is far and away the biggest component of the runtime. That doesn't feel right, but I don't know if an operator can be profiled (it would be great if it could).
I am suspicious that the true time it takes to complete the CALL_EXTERNAL is not being computed correctly. Is this a known issue? Can anyone explain what might be going on here?
|
|
|