Hands-On: Timing Violation Investigation

// Step 1: STM profiling — coarse-grained identification
// Add PROF_START/END to each runnable temporarily
// Or: use ETM profiling without any source modification

ETM.ON
ETM.DataTrace NONE
Trace.METHOD Analyzer
Trace.Size 64MB

Go
WAIT 2s
Break

// Generate flat profile
Trace.Statistics.Func /MAX
// Expected output (sorted by total time):
// 1. NvM_MainFunction         43.2%   avg=4.2ms  max=12.1ms  calls=10
// 2. Can_MainFunction          18.3%   avg=1.8ms  max=3.2ms   calls=10
// 3. Com_MainFunction           7.1%   avg=0.7ms  max=0.9ms   calls=10
//
// NvM_MainFunction worst-case 12.1ms in a 10ms task → violation culprit

// Drill into NvM: which NvM operations are slow?
Trace.Statistics.Func "NvM*"    // wildcard: all NvM_ functions
// NvM_WriteBlock called with 1024-byte block per cycle — excessive

// Step 2: MCDS cache miss analysis
MCDS.ON
MCDS.PerfCounter DMISS
MCDS.PerfCounter.RESET

// Profile only NvM_MainFunction
Break.Set NvM_MainFunction /Program
Go ; WAIT !STATE.RUN() 2s
LOCAL &t_start
&t_start=Data.Long(SFR:STM0.TIM0)
MCDS.PerfCounter.RESET
Go NvM_Return    // run to return
WAIT !STATE.RUN() 50ms

LOCAL &dmiss &duration
&dmiss=MCDS.PerfCounter.VALUE(DMISS)
&duration=(Data.Long(SFR:STM0.TIM0)-&t_start)/300.
PRINT "NvM DCACHE misses: " &dmiss " in " FORMAT.FLOAT(2.,1.,&duration) " µs"
// Expected: 4800 D-cache misses in 4200µs = ~1.14 misses/µs
// Each miss: ~30-cycle bus stall = ~100ns → 480µs lost to cache misses

// Inspect data structure layout
Var.View %Size (NvM_BlockDescriptor_t *)g_nvmBlocks
// Each descriptor: 128 bytes; array of 64 = 8192 bytes = 256 cache lines
// Access pattern: random by block ID → poor spatial locality → high miss rate

// Fix: sort blocks by access frequency; pack hot fields to first 32 bytes per struct

// After fix: NvM descriptors reordered (hot fields first + sorted by access frequency)
// Rebuild and reflash: aurix_pflash.cmm with new ELF

Data.LOAD.Elf timing_lab_fixed.elf
SYStem.Reset

// Re-run ETM profile with fixed code
ETM.ON
Trace.METHOD Analyzer
Trace.Size 64MB
Go
WAIT 2s
Break

// Compare profiles
Trace.Statistics.Func /MAX
// Expected after fix:
// 1. NvM_MainFunction  22.1%  avg=2.1ms  max=3.4ms  (was avg=4.2ms max=12.1ms)
// 2. Can_MainFunction  18.3%  avg=1.8ms  max=3.2ms  (unchanged)

// Verify task timing now within budget
Trace.Chart.TASK
// OsTask_10ms now stays comfortably under 10ms on every activation

// Run 1000 cycles to confirm no residual overruns
LOCAL &overruns
&overruns=0.
LOCAL &i
&i=0.
WHILE &i<1000.
(
    Go OsTask_10ms_Entry ; WAIT !STATE.RUN() 100ms
    LOCAL &t1
    &t1=Data.Long(SFR:STM0.TIM0)
    Go OsTask_10ms_Exit  ; WAIT !STATE.RUN() 100ms
    LOCAL &t2
    &t2=Data.Long(SFR:STM0.TIM0)
    IF (&t2-&t1)>3000000.   // 10ms in 300MHz ticks
        &overruns=&overruns+1.
    &i=&i+1.
)
PRINT "Overruns in 1000 cycles: " &overruns " (expected: 0)"