Contract between NNAPI systrace code and parser
===============================================
This text files documents how tracing in the NNAPI manifests in systrace output
and how that output is interpreted by the systrace parser.
Please view in a 160 character window.
Special cases
-------------
- Execution is exposed as an asynchronous event from the runtime. Time taken
by the runtime is calculated as the time between start of
ANeuralNetworksExecution_startCompute and end of
ANeuralNetworksEvent_wait. This special case is not reflected in the cases
presented below.
Notation
--------
- ...: elided code
- t_m_w: tracing_mark_write
- tX: timestamps
- T1, T2: thread ids
Cases for the parser
====================
Source code Systrace Interpretation for timing statistics - all
times are wallclock
------------------------------------------------------------------------------------------------------------------------------------------------------
*Baseline case*
... funcP(...) { t0: t_m_w:B|T1|[NN_LR_PP]funcP Add (t1-t0) to total time spent in Layer
NNTRACE_RT(NNTRACE_PHASE_PREPARATION, t1: t_m_w:E|T1 Runtime, Phase Preparation
"funcP);
...
}
------------------------------------------------------------------------------------------------------------------------------------------------------
*Local call to other layer*
... funcA1(...) { t0: t_m_w:B|T1|[NN_LA_PP]funcE1 Add (t3-t0) to total time spent in Layer
NNTRACE_APP(NNTRACE_PHASE_PREPARATION, t1: t_m_w:B|T1|[NN_LR_PP]funcC1 Application, Phase Preparation
"funcA1); t2: t_m_w:E|T1
... funcR1(...); t3: t_m_w:E|T1 Add (t2-t1) to total time spent in Layer
... Runtime, Phase Preparation
}
... funcR1(...) { Note: Self-time of Layer Application,
NNTRACE_RT(NNTRACE_PHASE_PREPARATION, Phase Preparation will be calculated as
"funcR1"); ... total time in Layer Application - total time
} in Layer Runtime
Note: These can be nested as per rows
below ("Switch phase ...", "Subphases ...",
"Additional detail...")
Note: If the called function specifies a
phase that is not supposed to be nested,
the parser will emit a diagnostic.
------------------------------------------------------------------------------------------------------------------------------------------------------
*Switch phase during function*
... funcC1(...) { t0: t_m_w:B|T1|[NN_LC_PTR]funcC1 Add (t1-t0) to total time spent in Layer
NNTRACE_TRANS("funcC1"); t1: t_m_w:B|T1|[SW][NN_LC_PCO]funcC1 CPU, Phase Transformation
... t2: t_m_w:E|T1
NNTRACE_COMP_SWITCH("funcC1"); t3: t_m_w:E|T1 Add (t2-t1) to total time spent in Layer
... CPU, Phase Computation
}
(t3-t2 treated as negligible - only the
destructors of objects created between
the tracepoints)
------------------------------------------------------------------------------------------------------------------------------------------------------
*Subphases of execution*
... funcR2(...) { t0: t_m_w:B|T1|[NN_LR_PE]funcR2 Add (t2-t1) to total time spent in Layer
NNTRACE_RT(NNTRACE_PHASE_EXECUTION, t1: t_m_w:B|T1|[NN_LC_PCO]funcC2 CPU, (sub)Phase Computation and to
"funcR2); t2: t_m_w:E|T1 total time in Phase Execution
... funcC2(...); t3: t_m_w:E|T1
... Add (t3-t0) to total time spent in Layer
} Runtime, Phase Execution
... funcC2(...) {
NNTRACE_COMP("funcC2");
...
}
------------------------------------------------------------------------------------------------------------------------------------------------------
*Additional detail in the same layer*
... funcR3(...) { t0: t_m_w:B|T1|[NN_LR_PE]funcR3 Add (t3-t0) to total time spent in Layer
NNTRACE_RT(NNTRACE_PHASE_EXECUTION, t1: t_m_w:B|T1|[NN_LR_PE]funcR4 Runtime, Phase Execution
"funcR3); t2: t_m_w:E|T1
... funcR4(...); t3: t_m_w:E|T1 Note: funcR4 will be visible in the systrace
... visualization
}
... funcR4(...) {
NNTRACE_RT(NNTRACE_PHASE_EXECUTION,
"funcR4");
...
}
------------------------------------------------------------------------------------------------------------------------------------------------------
*Synchronous IPC call*
... funcR5(...) { t0: t_m_w:B|T1|[NN_LR_PC]funcR5 Add (t5-t0) - (t4-r1) to total time spent in
NNTRACE_RT(NNTRACE_PHASE_COMPILATION, t1: t_m_w:B|T1|[NN_LI_PI]getCapabilities Layer Runtime, Phase Compilation; see
"funcR5"); t2: t_m_w:B|T1|HIDL::IDevice::getCapabilities::client "Onetime initialization code".
... device->getCapabilities() t3: t_m_w:E|T1
... t4: t_m_w:E|T1 Add (t4-t1) to total time spent in Layer
} t5: t_m_w:E|T1 IPC, Phase Initialization
... VersionedIDevice::getCapabilities(...) {
NTRACE_FULL(NNTRACE_LAYER_IPC, Note: Self-time of Layer Runtime, Phase
NNTRACE_PHASE_COMPILATION, Compilation will be calculated as total
"getCapabilities"); time in Layer Runtime - total time in Layer
IPC
}
Note: Tracepoints are needed for the
client IPC calls. The HIDL tracing isn't
guaranteed to wait for the server - it just
sends the transaction even if the call is
synchronous.
------------------------------------------------------------------------------------------------------------------------------------------------------
*Asynchronous IPC call that is synchronously waited for by the runtime*
// Runtime code t0: t_m_w:B|T1|[NN_LI_PC]prepareModel Add (t10-t0) to total time spent in Layer
... funcRC(...) { t1: t_m_w:B|T1|HIDL::IDevice::prepareModel_1_1::client IPC, Phase Compilation
... t2: t_m_w:B|T2|HIDL::IDevice::prepareModel_1_1::server
NTRACE_FULL(NNTRACE_LAYER_IPC, t3: t_m_w:B|T2|[NN_LD_PC]SampleDriver::prepareModel Add (t6-t2) to total time spent in Layer
NNTRACE_PHASE_COMPILATION, t4: t_m_w:B|T2|HIDL::IPreparedModelCallback::notify::clie Driver, Phase Compilation. This includes
"prapareModel"); t5: t_m_w:E|T2 the generated HIDL stub code, which is
... t6: t_m_w:E|T2 <0.05ms.
device->prepareModel(...); t7: t_m_w:E|T2
... t8: t_m_w:B|T1|HIDL::IPreparedModelCallback::notify::serv Note: the HIDL trace rows are added by
cb->wait(); t9: t_m_w:E|T1 the automatically generated proxy and
... t10: t_m_w:E|T1 stub code. For the driver side, the
} t11: t_m_w:E|T1 mapping of the HIDL functions to layers
and phases is done in the systrace
// Driver code parser.
... SampleDriver::prepareModel(...) {
NNTRACE_FULL(NNTRACE_LAYER_DRIVER, Note: the SampleDriver::prepareModel is
NNTRACE_PHASE_COMPILATION, treated as additional detail for Layer
"SampleDriver::prepareModel"); Driver, Phase Compilation.
}
Note: the "t_m_w" output of
systrace uses thread ids, so that the call
stack can be reconstructed. The systrace
rows are also annotated with process ids.
The parser uses the process ids to
distinguish between the application
process from the driver process (used for
diagnostics and for distinguishing CPU
fallback from sample driver).
Note: the next row in this table gives more
detail for prepareModel specifically
Note: the driver-side HIDL traces get us
the time spent in sample and hvx drivers.
With a different driver threading model
this may not be the case - future drivers
should add manual tracing.
TODO: attribute driver process IPC call
(callback) overhead to IPC layer.
------------------------------------------------------------------------------------------------------------------------------------------------------
*Subtracting time when nesting is violated*
// Runtime code t0: t_m_w:B|T1|[NN_LI_PC]prepareModel Add (t3 - t0) - (t2 - t1) to total time spent
... funcRC(...) { t1: t_m_w:B|T1|[SUB][NN_LR_PC]VersionedIDevice::prepareM in Layer IPC, Phase compilation
... t2: t_m_w:E|T1
NTRACE_FULL(NNTRACE_LAYER_IPC, t3: t_m_w:E|T1 Add (t2-t1) to total time spent in Layer
NNTRACE_PHASE_COMPILATION, Runtime, Phase compilation
"prapareModel");
...
device->prepareModel(...);
...
cb->wait();
...
}
... VersionedIDevice::prepareModel(...) {
// IPC work
{
NNTRACE_FULL_SUBTRACT(
NNTRACE_LAYER_RUNTIME,
NNTRACE_PHASE_COMPILATION,
"VersionedIDevice::prepareModel");
// Runtime work
}
// IPC work
}
------------------------------------------------------------------------------------------------------------------------------------------------------
*Onetime initialization code*
... funcR5(...) { t0: t_m_w:B|T1|[NN_LR_PP]funcR5 Add (t2-t1) to total time spent in Layer
NNTRACE_RT(NNTRACE_PHASE_PREPARATION, t1: t_m_w:B|T1|[NN_LR_PI]funcI Runtime, Phase Initialization
"runcR5); t2: t_m_w:E|T1
... funcI(...); t3: t_m_w:E|T1 Add (t3 - t0) - (t2 - t1) to total time spent
... in Layer Runtime, Phase Preparation.
}
... funcI(...) {
NNTRACE_RT(NNTRACE_PHASE_INITIALIZATION,
"funcI")
...
}
------------------------------------------------------------------------------------------------------------------------------------------------------
*Utility code*
... funcR6(...) { t0: t_m_w:B|T1|[NN_LR_PP]funcR6 Add (t3-t0) to total time spent in Layer
NNTRACE_RT(NNTRACE_PHASE_PREPARATION, t1: t_m_w:B|T1|[NN_LU_PU]funcU Runtime, Phase Preparation
"funcR6"); t2: t_m_w:E|T1
... funcU(...); t3: t_m_w:E|T1 Note: the funcU is treated as additional
... detail.
}
... funcU(...) {
NNTRACE_FULL(NNTRACE_LAYER_UTILITY,
NNTRACE_PHASE_UNSPECIFIED,
"funcU")
...
}