Perf Trace Improvements (#1383)

* add tid field to thread

* change perf trace format

* trace consumers

* Update java parsing

* guard for test + kinetis

* stubs

* ram

Co-authored-by: Matthew Kennedy <makenne@microsoft.com>
This commit is contained in:
Matthew Kennedy 2020-04-29 07:53:35 -07:00 committed by GitHub
parent 67485582aa
commit 1f16228bdb
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
13 changed files with 86 additions and 110 deletions

View File

@ -33,4 +33,5 @@ LoggingWithStorage::LoggingWithStorage(const char *name) : Logging(name, DEFAULT
void irqEnterHook() {}
void irqExitHook() {}
void contextSwitchHook() {}
void threadInitHook(void*) {}
//#endif /* ENABLE_PERF_TRACE */

View File

@ -641,26 +641,6 @@
/* Add threads initialization code here.*/ \
}
/**
* @brief Threads descriptor structure extension.
* @details User fields added to the end of the @p thread_t structure.
*/
#define CH_CFG_THREAD_EXTRA_FIELDS \
void *activeStack; \
int remainingStack; \
/* Add threads custom fields here.*/
/**
* @brief Threads initialization hook.
* @details User initialization code added to the @p chThdInit() API.
*
* @note It is invoked from within @p chThdInit() and implicitly from all
* the threads creation APIs.
*/
#define CH_CFG_THREAD_INIT_HOOK(tp) { \
/* Add threads initialization code here.*/ \
}
/**
* @brief Threads finalization hook.
* @details User finalization code added to the @p chThdExit() API.

View File

@ -21,6 +21,7 @@ extern "C"
void irqEnterHook(void);
void irqExitHook(void);
void contextSwitchHook(void);
void threadInitHook(void* tp);
#endif /* __ASSEMBLER__ */
#ifdef __cplusplus
}
@ -85,4 +86,23 @@ extern "C" {
irqExitHook(); \
}
/**
* @brief Threads descriptor structure extension.
* @details User fields added to the end of the @p thread_t structure.
*/
#define CH_CFG_THREAD_EXTRA_FIELDS \
void *activeStack; \
int remainingStack; \
unsigned char threadId; \
/* Add threads custom fields here.*/
/**
* @brief Threads initialization hook.
* @details User initialization code added to the @p chThdInit() API.
*
* @note It is invoked from within @p chThdInit() and implicitly from all
* the threads creation APIs.
*/
#define CH_CFG_THREAD_INIT_HOOK(tp) { threadInitHook(tp); }
#endif /* CONFIG_CHCONF_COMMON_H_ */

View File

@ -632,26 +632,6 @@
/* Add threads initialization code here.*/ \
}
/**
* @brief Threads descriptor structure extension.
* @details User fields added to the end of the @p thread_t structure.
*/
#define CH_CFG_THREAD_EXTRA_FIELDS \
void *activeStack; \
int remainingStack; \
/* Add threads custom fields here.*/
/**
* @brief Threads initialization hook.
* @details User initialization code added to the @p chThdInit() API.
*
* @note It is invoked from within @p chThdInit() and implicitly from all
* the threads creation APIs.
*/
#define CH_CFG_THREAD_INIT_HOOK(tp) { \
/* Add threads initialization code here.*/ \
}
/**
* @brief Threads finalization hook.
* @details User finalization code added to the @p chThdExit() API.

View File

@ -632,26 +632,6 @@
/* Add threads initialization code here.*/ \
}
/**
* @brief Threads descriptor structure extension.
* @details User fields added to the end of the @p thread_t structure.
*/
#define CH_CFG_THREAD_EXTRA_FIELDS \
void *activeStack; \
int remainingStack; \
/* Add threads custom fields here.*/
/**
* @brief Threads initialization hook.
* @details User initialization code added to the @p chThdInit() API.
*
* @note It is invoked from within @p chThdInit() and implicitly from all
* the threads creation APIs.
*/
#define CH_CFG_THREAD_INIT_HOOK(tp) { \
/* Add threads initialization code here.*/ \
}
/**
* @brief Threads finalization hook.
* @details User finalization code added to the @p chThdExit() API.

View File

@ -732,7 +732,7 @@ void initEngineContoller(Logging *sharedLogger DECLARE_ENGINE_PARAMETER_SUFFIX)
// help to notice when RAM usage goes up - if a code change adds to RAM usage these variables would fail
// linking process which is the way to raise the alarm
#ifndef RAM_UNUSED_SIZE
#define RAM_UNUSED_SIZE 14500
#define RAM_UNUSED_SIZE 14300
#endif
#ifndef CCM_UNUSED_SIZE
#define CCM_UNUSED_SIZE 2900

View File

@ -15,6 +15,12 @@ EXTERN_ENGINE;
extern LoggingWithStorage sharedLogger;
#if ENABLE_PERF_TRACE
static uint8_t nextThreadId = 0;
void threadInitHook(void* vtp) {
// No lock required, this is already under lock
auto tp = reinterpret_cast<thread_t*>(vtp);
tp->threadId = ++nextThreadId;
}
void irqEnterHook() {
perfEventBegin(PE::ISR);
@ -29,6 +35,7 @@ void contextSwitchHook() {
}
#else
void threadInitHook(void*) {}
void irqEnterHook() {}
void irqExitHook() {}
void contextSwitchHook() {}

View File

@ -227,7 +227,7 @@ uint32_t triggerDuration;
uint32_t triggerMaxDuration = 0;
void hwHandleShaftSignal(trigger_event_e signal, efitick_t timestamp) {
ScopePerf perf(PE::HandleShaftSignal, static_cast<uint8_t>(signal));
ScopePerf perf(PE::HandleShaftSignal);
#if EFI_TOOTH_LOGGER
// Log to the Tunerstudio tooth logger

View File

@ -383,7 +383,7 @@ void TriggerState::onShaftSynchronization(const TriggerStateCallback triggerCycl
void TriggerState::decodeTriggerEvent(TriggerWaveform *triggerShape, const TriggerStateCallback triggerCycleCallback,
TriggerStateListener * triggerStateListener,
trigger_event_e const signal, efitick_t nowNt DECLARE_CONFIG_PARAMETER_SUFFIX) {
ScopePerf perf(PE::DecodeTriggerEvent, static_cast<uint8_t>(signal));
ScopePerf perf(PE::DecodeTriggerEvent);
if (nowNt - previousShaftEventTimeNt > NT_PER_SECOND) {
/**

View File

@ -27,7 +27,7 @@ struct TraceEntry
{
PE Event;
EPhase Phase;
uint8_t Data;
int8_t IsrId;
uint8_t ThreadId;
uint32_t Timestamp;
};
@ -41,7 +41,7 @@ static size_t s_nextIdx = 0;
static bool s_isTracing = false;
void perfEventImpl(PE event, EPhase phase, uint8_t data)
static void perfEventImpl(PE event, EPhase phase)
{
// Bail if we aren't allowed to trace
if constexpr (!ENABLE_PERF_TRACE) {
@ -81,22 +81,31 @@ void perfEventImpl(PE event, EPhase phase, uint8_t data)
entry.Event = event;
entry.Phase = phase;
// Get the current active interrupt - this is the "thread ID"
entry.ThreadId = static_cast<uint8_t>(SCB->ICSR & SCB_ICSR_VECTACTIVE_Msk);
// Get the current active interrupt - this is the "process ID"
auto isr = static_cast<int8_t>(SCB->ICSR & SCB_ICSR_VECTACTIVE_Msk);
entry.IsrId = isr - 16;
// Get the current thread (if not interrupt) and use as the thread ID
if (isr == 0) {
entry.ThreadId = chThdGetSelfX()->threadId;
} else {
// Interrupts have no thread - all are T0
entry.ThreadId = 0;
}
entry.Timestamp = timestamp;
entry.Data = data;
}
void perfEventBegin(PE event, uint8_t data) {
perfEventImpl(event, EPhase::Start, data);
void perfEventBegin(PE event) {
perfEventImpl(event, EPhase::Start);
}
void perfEventEnd(PE event, uint8_t data) {
perfEventImpl(event, EPhase::End, data);
void perfEventEnd(PE event) {
perfEventImpl(event, EPhase::End);
}
void perfEventInstantGlobal(PE event, uint8_t data) {
perfEventImpl(event, EPhase::InstantGlobal, data);
void perfEventInstantGlobal(PE event) {
perfEventImpl(event, EPhase::InstantGlobal);
}
void perfTraceEnable() {

View File

@ -65,9 +65,9 @@ enum class PE : uint8_t {
// please note that the tool requires a comma at the end of last value
};
void perfEventBegin(PE event, uint8_t data = 0);
void perfEventEnd(PE event, uint8_t data = 0);
void perfEventInstantGlobal(PE event, uint8_t data = 0);
void perfEventBegin(PE event);
void perfEventEnd(PE event);
void perfEventInstantGlobal(PE event);
// Enable one buffer's worth of perf tracing, and retrieve the buffer size in bytes
void perfTraceEnable();
@ -85,28 +85,23 @@ const TraceBufferResult perfTraceGetBuffer();
class ScopePerf
{
public:
ScopePerf(PE event) : ScopePerf(event, 0) {}
ScopePerf(PE event, uint8_t data) : m_event(event), m_data(data)
{
perfEventBegin(event, data);
ScopePerf(PE event) : m_event(event) {
perfEventBegin(event);
}
~ScopePerf()
{
perfEventEnd(m_event, m_data);
perfEventEnd(m_event);
}
private:
const PE m_event;
const uint8_t m_data;
};
#else /* if ENABLE_PERF_TRACE */
struct ScopePerf {
ScopePerf(PE event) { (void)event; }
ScopePerf(PE event, uint8_t data) { (void)event; (void)data; }
ScopePerf(PE) {}
};
#endif /* ENABLE_PERF_TRACE */

View File

@ -14,11 +14,15 @@ public class Entry {
private static final double MAGIC_NT = 168.0;
private final String name;
private final Phase phase;
private final int isr;
private final int thread;
private double timestampSeconds;
public Entry(String name, Phase phase, double timestampSeconds) {
public Entry(String name, Phase phase, double timestampSeconds, int isr, int thread) {
this.name = name;
this.phase = phase;
this.isr = isr;
this.thread = thread;
this.timestampSeconds = timestampSeconds;
}
@ -65,7 +69,7 @@ public class Entry {
for (int i = 0; i < packet.length - 1; i += 8) {
byte type = is.readByte();
byte phase = is.readByte();
byte data = is.readByte();
byte isr = is.readByte();
byte thread = is.readByte();
int timestampNt = readInt(is);
@ -91,7 +95,7 @@ public class Entry {
name = TypeNames[type];
}
Entry e = new Entry(name, Phase.decode(phase), timestampSeconds);
Entry e = new Entry(name, Phase.decode(phase), timestampSeconds, isr, thread);
result.add(e);
}
@ -119,10 +123,9 @@ public class Entry {
sb.append(",");
AppendKeyValuePair(sb, "ph", phase.toString());
sb.append(",");
AppendKeyValuePair(sb, "tid", 0);
AppendKeyValuePair(sb, "tid", thread);
sb.append(",");
AppendKeyValuePair(sb, "pid", 0);
AppendKeyValuePair(sb, "pid", isr);
sb.append(",");
AppendKeyValuePair(sb, "ts", timestampSeconds);
sb.append("}");

View File

@ -15,25 +15,26 @@ public class JsonOutput {
/**
* those are special entries that change display settings
* those set thread names and sort index based on those thread IDs
* (those thread IDs are interrupt numbers, and the name is the name of the interrupt handler)
* (those process IDs are interrupt numbers, and the name is the name of the interrupt handler)
*/
private static final String FORMATTING_SETTINGS
= "{\"name\":\"thread_name\",\"ph\":\"M\",\"tid\":18,\"pid\":0,\"args\":{\"name\":\"ADC\"}}," +
"{\"name\":\"thread_name\",\"ph\":\"M\",\"tid\":29,\"pid\":0,\"args\":{\"name\":\"TIM3\"}}," +
"{\"name\":\"thread_name\",\"ph\":\"M\",\"tid\":30,\"pid\":0,\"args\":{\"name\":\"TIM4\"}}," +
"{\"name\":\"thread_name\",\"ph\":\"M\",\"tid\":44,\"pid\":0,\"args\":{\"name\":\"TIM8/13\"}}," +
"{\"name\":\"thread_name\",\"ph\":\"M\",\"tid\":50,\"pid\":0,\"args\":{\"name\":\"TIM5\"}}," +
"{\"name\":\"thread_name\",\"ph\":\"M\",\"tid\":58,\"pid\":0,\"args\":{\"name\":\"DMA2s2\"}}," +
"{\"name\":\"thread_name\",\"ph\":\"M\",\"tid\":60,\"pid\":0,\"args\":{\"name\":\"DMA2s4\"}}," +
"{\"name\":\"thread_name\",\"ph\":\"M\",\"tid\":67,\"pid\":0,\"args\":{\"name\":\"USB\"}}," +
"{\"name\":\"thread_sort_index\",\"ph\":\"M\",\"tid\":18,\"pid\":0,\"args\":{\"sort_index\":4}}," +
"{\"name\":\"thread_sort_index\",\"ph\":\"M\",\"tid\":29,\"pid\":0,\"args\":{\"sort_index\":2}}," +
"{\"name\":\"thread_sort_index\",\"ph\":\"M\",\"tid\":30,\"pid\":0,\"args\":{\"sort_index\":5}}," +
"{\"name\":\"thread_sort_index\",\"ph\":\"M\",\"tid\":44,\"pid\":0,\"args\":{\"sort_index\":7}}," +
"{\"name\":\"thread_sort_index\",\"ph\":\"M\",\"tid\":50,\"pid\":0,\"args\":{\"sort_index\":3}}," +
"{\"name\":\"thread_sort_index\",\"ph\":\"M\",\"tid\":58,\"pid\":0,\"args\":{\"sort_index\":6}}," +
"{\"name\":\"thread_sort_index\",\"ph\":\"M\",\"tid\":60,\"pid\":0,\"args\":{\"sort_index\":8}}," +
"{\"name\":\"thread_sort_index\",\"ph\":\"M\",\"tid\":67,\"pid\":0,\"args\":{\"sort_index\":9}}"
private static final String FORMATTING_SETTINGS =
"{\"name\":\"process_name\",\"ph\":\"M\",\"pid\":-16,\"tid\":0,\"args\":{\"name\":\"Main\"}}," +
"{\"name\":\"process_name\",\"ph\":\"M\",\"pid\":-1,\"tid\":0,\"args\":{\"name\":\"SysTick\"}}," +
"{\"name\":\"process_name\",\"ph\":\"M\",\"pid\":18,\"tid\":0,\"args\":{\"name\":\"ADC\"}}," +
"{\"name\":\"process_name\",\"ph\":\"M\",\"pid\":19,\"tid\":0,\"args\":{\"name\":\"CAN1 TX\"}}," +
"{\"name\":\"process_name\",\"ph\":\"M\",\"pid\":20,\"tid\":0,\"args\":{\"name\":\"CAN1 RX 0\"}}," +
"{\"name\":\"process_name\",\"ph\":\"M\",\"pid\":21,\"tid\":0,\"args\":{\"name\":\"CAN1 RX 1\"}}," +
"{\"name\":\"process_name\",\"ph\":\"M\",\"pid\":22,\"tid\":0,\"args\":{\"name\":\"CAN1 SCE\"}}," +
"{\"name\":\"process_name\",\"ph\":\"M\",\"pid\":29,\"tid\":0,\"args\":{\"name\":\"TIM3\"}}," +
"{\"name\":\"process_name\",\"ph\":\"M\",\"pid\":30,\"tid\":0,\"args\":{\"name\":\"TIM4\"}}," +
"{\"name\":\"process_name\",\"ph\":\"M\",\"pid\":44,\"tid\":0,\"args\":{\"name\":\"TIM8/13\"}}," +
"{\"name\":\"process_name\",\"ph\":\"M\",\"pid\":50,\"tid\":0,\"args\":{\"name\":\"TIM5\"}}," +
"{\"name\":\"process_name\",\"ph\":\"M\",\"pid\":54,\"tid\":0,\"args\":{\"name\":\"TIM6\"}}," +
"{\"name\":\"process_name\",\"ph\":\"M\",\"pid\":57,\"tid\":0,\"args\":{\"name\":\"DMA2s1\"}}," +
"{\"name\":\"process_name\",\"ph\":\"M\",\"pid\":58,\"tid\":0,\"args\":{\"name\":\"DMA2s2\"}}," +
"{\"name\":\"process_name\",\"ph\":\"M\",\"pid\":59,\"tid\":0,\"args\":{\"name\":\"DMA2s3\"}}," +
"{\"name\":\"process_name\",\"ph\":\"M\",\"pid\":60,\"tid\":0,\"args\":{\"name\":\"DMA2s4\"}}," +
"{\"name\":\"process_name\",\"ph\":\"M\",\"pid\":67,\"tid\":0,\"args\":{\"name\":\"USB\"}},"
;
private static final String EOL = "\r\n";