The following APIs can be used to write into the smem log.
void smem_log_event ( smem_log_area area, uint32 id, uint32 reserved,
uint32 data1, uint32 data2, uint32 data3 );
void smem_log_event6 ( smem_log_area area, uint32 id, uint32 reserved,
uint32 data1, uint32 data2, uint32 data3,
uint32 data4, uint32 data5, uint32 data6);
Note that the sleep_log_event also writes to the smem log (both circular and power circular
buffers) when FEATURE_SMEM_LOG is defined. If smem log is not available, it writes to
sleep_trace.
void sleep_log_event
(
/* Event to be logged */
uint32 event,
)
Arbitrary data to log */ uint32 a32, uint32 b32, uint32 c32
Here are some commonly used MACROs defined based on smem_log_event APIs.
#define SMEM_LOG_EVENT(identifier,data1,data2,data3) \
smem_log_event(SMEM_LOG_AREA_CIRCULAR_MPROC, \
identifier, 0, data1, data2, data3)
#define SMEM_LOG_EVENT_EX(area, id, reserved, data1, data2, data3) \
smem_log_event(area, id, reserved, data1, data2, data3)
#define DEM_LOG_EVENT(event, data1, data2, data3) \
SMEM_LOG_EVENT(event, data1, data2, data3)
#define ONCRPC_LOG_EVENT(event, data1, data2, data3) \
SMEM_LOG_EVENT( event, data1, data2, data3 )
#define CLKREGIM_SMEM_LOG_EVENT(a,b,c,d) \
SMEM_LOG_EVENT_EX(SMEM_LOG_AREA_CIRCULAR_POWER, \
SMEM_LOG_CLKREGIM_##a, 0, b, c, d)
Collecting SMEM log
To collect the shared memory log, you need first run the smemlog.cmm script in
\AMSS\products\7x30\tools\debug from T32.
do smemlog.cmm C:\temp
You can replace C:\temp with a directory where you want the output files to be saved. This script
prints out several *.lst files, which contain raw smemlog data dumped from device memory.
To parse these output files into readable version of log information, you can run the smem_log.pl
script from a command window, e.g., you can parse the log and save it as a .txt file.
perl smem_log.pl [-t] > smemlog.txt
The optional -t parameter will force timestamps to show up in native slow clock ticks. This can be
useful when you need to compare smemlog to other logs such as tramp_log, mao_trace, etc.
Without this option, the timestamps are converted into seconds.
The output of smem_log.pl includes several entries for each RPC call. If you are not interested in
the RPC messages, you can run smem_log_filter.pl to filter RPC-related messages out of the log,
e.g.:
perl smem_log.pl | perl smem_log_filter.pl > smemlog_filter.txt
perl smem_log_filter.pl smemlog.txt > smemlog_filter.txt
Reading SMEM log
Modem deep sleep
The shared memory log contains very useful information on the device's sleep operation. A
parsed smem log entry often takes the following format.
Processor: Timestamp Module: Event data1 data2 data3
For instance, the following logs show that the Sleep module of the modem recorded this entry at
101.890594 secs when the modem decided to enter deep sleep. The first data item shows that the
prescribed sleep time is 0x1004 slow clock ticks (~128 ms).
MODM: 101.890594 SLEEP: ENTER TCXO 1004 0 0
If we look at the code, we can see this log entry is recorded by the following line of
sleepmod_tcxo_shutdown.
sleep_log_event( MOD_ENTER_TCXO, uNextWakeupSclk, 0, 0 );
The above log should always be accompanied by a TCXO END smem log entry such as follows.
MODM: 102.012438 SLEEP: TCXO END 0 1 0
Similarly, this entry is logged by the following line inside the same API.
sleep_log_event( MOD_TCXO_END, 0, maoint_get_pending_ints(), 0 );
Therefore, we know the modem came out of deep sleep at 102.012438 sec, and the total sleep
time is about 122 ms, which is close to the prescribed sleep time. This is also explained by the
fact that the modem is awakened from deep sleep by MAO interrupt at bit 0, which is the timer
interrupt in the MPM block.
102.012438 - 101.890594 = 0.121844
Fail to enter deep sleep
Besides deep sleep events, the modem also logs the reason why it did not enter deep sleep when
the sleep task gets a chance to run, e.g., the following log entry shows that at 102.017813 sec, the
modem was prevented from entering deep sleep because there was insufficient time.
MODM: 102.017813 SLEEP: INSUF TIME 0000353c 0000001d ffffffff
This is logged by the following code.
sleep_log_event( INSUF_TIME, uNextSleepCtlSclk, uNextTimerSclk,
uNextAltSclk );
Therefore, we know the modem could not sleep because there is a software timer expiration in
0x1d ticks, but smem log does not log which software timer it was. Examining timer_trace when
available should tell what timer expired after this event.
Sometimes the modem cannot enter deep sleep because certain modules are voting against it, e.g.,
the following logs show that at different times CLKREGIM, WL1, APROC, and ADC were
voting against sleep.
MODM: 101.790875 SLEEP: NO SLEEP - CLKREGIM WL1
MODM: 101.889313 SLEEP: NO SLEEP � APROC
MODM: 109.661563 SLEEP: NO SLEEP - WL1
MODM: 110.957969 SLEEP: NO SLEEP - ADC
Besides sleep votes, the shared memory log also shows when sleep resources are
acquired/released by modules. The following log sequence shows that WL1 acquired the sleep
resources and this caused the modem to not be able to enter deep sleep. Later when WL1 released
these resources, the modem did an XO shutdown.
MODM: 109.661438 SLEEP: RESOURCE ACQUIRED: resources TCXO MEMORY
VDD_MIN APPS_SLEEP APPS_PWRC by WL1
MODM: 109.661563 SLEEP: NO SLEEP - WL1
MODM: 109.676063 SLEEP: RESOURCE RELEASED: resources TCXO MEMORY
VDD_MIN APPS_SLEEP APPS_PWRC last voter WL1
MODM: 109.677156 SLEEP: ENTER TCXO 00004e7e 0 0
MODM: 110.298688 SLEEP: TCXO END 0 1 0
Apps sleep
The following shows a sequence of DEM logs when apps enters sleep.
MODM: 100.046031 DEM: SMSM ISR: entry: APPS DEM STATE cleared bits: RUN
set bits: SLEEP
MODM: 100.046094 DEM: STATE_MACHINE_ENTER 0 0
0
MODM: 100.046125 DEM: STATE CHANGE: master leaving RUN and entering
SLEEP WAIT
MODM: 100.046156 DEM: SETUP SLEEP 0 0000062d 0
MODM: 100.04675 DEM: APPS SWFI 0 0 0
MODM: 100.046781 DEM: STATE CHANGE: master leaving SLEEP WAIT and
entering SLEEP CONFIRMED
MODM: 100.046781 DEM: ASSERT OKTS 0 0 0
It starts when the modem receives an SMSM state transition from apps, which notifies the modem
that apps has switched from the Run to the Sleep state. Accordingly, the modem responded by
transitioning the DEM master state from Run to SLEEP_WAIT, and set up apps for sleep with
sleep time 0x62d (~49.4 ms). Then the modem receives the SWFI_IRQ when apps enters the
SWFI state, and updates the DEM master state from SLEEP_WAIT to SLEEP_CONFIRMED.
Afterwards, DEM master asserts OKTS on behalf of apps.
The following is the corresponding wakeup sequence for this apps sleep.
MODM: 100.095688 DEM: TIMER EXPIRED 2 0 0
MODM: 100.095688 DEM: STATE_MACHINE_ENTER 1 1
0
MODM: 100.095688 DEM: STATE CHANGE: master leaving SLEEP CONFIRMED and
entering SLEEP EXIT
MODM: 100.095688 DEM: NEGATE OKTS 1 0 0
MODM: 100.095719 DEM: SEND WAKEUP 0 0 0
MODM: 100.095875 DEM: SMSM ISR: entry: APPS DEM STATE cleared bits:
SLEEP set bits: SLEEP_EXIT
MODM: 100.096031 DEM: SMSM ISR: entry: APPS DEM STATE cleared bits:
SLEEP_EXIT set bits: RUN
MODM: 100.096125 DEM: STATE_MACHINE_ENTER 1 1
0
MODM: 100.096125 DEM: DETECT RUN 0 0 0
MODM: 100.096125 DEM: STATE CHANGE: master leaving SLEEP EXIT and
entering RUN
MODM: 100.09625 SLEEP: NO SLEEP - CLKREGIM APROC
We can see that DEM first detects that apps sleep time has expired after about 49 ms. Thus, it
transitions the DEM master state from SLEEP_CONFIRMED to SLEEP_EXIT, votes against
sleep, and sends out a wakeup interrupt. When apps comes out of sleep, it switches the SMSM
state (from SLEEP to SLEEP_EXIT, then to RUN) and notifies DEM master. Once the modem
detects that apps is now in the Run state, it transitions the DEM master state from SLEEP_EXIT
to RUN. As a result, we see that apps shows up in the list of modules that votes against sleep.
Apps power collapse goes through similar handshaking and the DEM state transitions. Once such
a sequence of entering apps power collapse is shown below.
MODM: 0xcf37bf89 DEM: SMSM ISR: entry: APPS DEM STATE cleared bits: RUN
set bits: PWRC
MODM: 0xcf37bfa9 DEM: STATE_MACHINE_ENTER 0 0
0
MODM: 0xcf37bfb2 DEM: STATE CHANGE: master leaving RUN and entering RSA
MODM: 0xcf37c02d DEM: SETUP POWER COLLAPSE 0 0
0
MODM: 0xcf37c0f9 DEM: APPS SWFI 0 0 0
MODM: 0xcf37c11c DEM: STATE_MACHINE_ENTER 1 0
0
MODM: 0xcf37c11e DEM: STATE CHANGE: master leaving RSA and entering RSA
CHECK INTS
MODM: 0xcf37c121 DEM: STATE CHANGE: master leaving RSA CHECK INTS and
entering RSA CONFIRMED
MODM: 0xcf37c123 DEM: REMOVE PROC PWR from APPS
MODM: 0xcf37c157 DEM: ASSERT OKTS 0 0 0
We can see that the apps first changes its SMSM state from RUN to PWRC, and the modem
DEM switches from RUN to RSA. After the modem prepares the apps for power collapse, apps
enters SWFI. Then the modem DEM checks interrupts, enters the RSA_CONFIRMED state,
removes power from the apps, and asserts OKTS.
The following is the corresponding waking-up sequence.
MODM: 0xcf37fe69 DEM: TIMER EXPIRED 2 0 0
MODM: 0xcf37fe6b DEM: STATE_MACHINE_ENTER 1 1
0
MODM: 0xcf37fe82 DEM: STATE CHANGE: master leaving RSA CONFIRMED and
entering RSA WAKING
MODM: 0xcf37fe85 DEM: NEGATE OKTS 2 0 0
MODM: 0xcf37fe8b DEM: RESTORE PROC PWR to APPS
MODM: 0xcf37ff39 DEM: SMSM ISR: entry: APPS DEM STATE cleared bits: PWRC
set bits: WFPI
MODM: 0xcf37ff44 DEM: STATE_MACHINE_ENTER 1 1
0
MODM: 0xcf37ff46 DEM: STATE CHANGE: master leaving RSA WAKING and
entering RSA RESTORE
MODM: 0xcf38006f DEM: TIME SYNC REQUEST from APPS
MODM: 0xcf380071 DEM: TIME SYNC START: servicing APPS
MODM: 0xcf38007b DEM: SMSM ISR: entry: APPS DEM STATE cleared bits: WFPI
TIME INIT set bits: RUN TIME REQUEST
MODM: 0xcf380083 DEM: TIME SYNC POLL from APPS
MODM: 0xcf380086 DEM: TIME SYNC SEND VALUE: sclk of -818413434 to APPS
MODM: 0xcf380088 DEM: SMSM ISR: entry: APPS DEM STATE cleared bits: TIME
REQUEST set bits: TIME POLL
MODM: 0xcf38008f DEM: TIME SYNC INIT from APPS, offset was 0
MODM: 0xcf380097 DEM: TIME SYNC DONE 0 0 0
MODM: 0xcf380099 DEM: SMSM ISR: entry: APPS DEM STATE cleared bits: TIME
POLL set bits: TIME INIT
MODM: 0xcf3800ac DEM: STATE_MACHINE_ENTER 1 1
0
MODM: 0xcf3800c8 DEM: STATE CHANGE: master leaving RSA RESTORE and
entering RUN
Besides DEM state transitions and negating OKTS, DEM also conducts a slow clock
synchronization when apps is exiting power collapse so that the slow clocks on two subsystems
remain synchronized. This is done by passing the slow clock tick on the modem to the apps
through the shared memory. The apps then calculates the delta to compensate for the difference.
Inserting SMEM log
It is often useful to insert additional smem logs in the code to debug sleep-related issues, e.g., the
following entry adds a new log event using the SMEM_LOG_EVENT macro.
SMEM_LOG_EVENT(0xa, 0, 0, 0);
Note that bits 27-16 of the event identifier is interpreted as the subsystem ID (event base), and
0x0 is DEBUG_EVENT_BASE.
/** Event base for debug log events. */
#define SMEM_LOG_DEBUG_EVENT_BASE 0x00000000
The above entry shows up in the smem log as a DEBUG log line as follows.
MODM: 108642.298250 DEBUG: 0000000a 00000000 00000000 00000000
Other logs
This section discusses a few additional useful logs for debugging sleep or power issues.
Tramp log
Interrupt logs are guarded by the FEATURE_TRAMP_LOG compiler switch. The tramp_log
provides a short history of interrupts.
typedef struct
{
tramp_log_event_type event;
tramp_irq_type irq;
uint32 timestamp;
tramp_pic_log_level_type level;
uint32 in_stack;
uint32 in_service;
} tramp_log_entry_type;
typedef struct
{
uint32 index;
tramp_log_entry_type entries[MAX_TRAMP_LOG_ENTRIES];
} tramp_log_type;
static tramp_log_type tramp_log;
To collect tramp_log, you can use the following command in T32 that is connected to a live target
or a T32 simulator that is loaded with a set of RAM dump to save the log into a tramp.txt file.
printer.file tramp.txt
wp.Var.View %o %i %hex tramp_log.index tramp_log.entries
For instance, the following sequence shows the handling of the SLEEP_TIMETICK_IRQ.
[0x2] = (event = TRAMP_LOG_EVENT_NEST_START = 0x0D, irq = TRAMP_NULL_IRQ =
0x0, timestamp = 0x03984FD0, level = TRAMP_LOG_LEVEL_0 = 0x0, in_stack =
0x1, in_service = 0x2),
[0x3] = (event = TRAMP_LOG_EVENT_ISR_START = 0x1, irq =
TRAMP_SLEEP_TIMETICK_IRQ = 0x25, timestamp = 0x03984FD0, level =
TRAMP_LOG_LEVEL_0 = 0x0, in_stack = 0x1, in_service = 0x2),
[0x4] = (event = TRAMP_LOG_EVENT_ISR_FINISH = 0x2, irq =
TRAMP_SLEEP_TIMETICK_IRQ = 0x25, timestamp = 0x03984FD1, level =
TRAMP_LOG_LEVEL_0 = 0x0, in_stack = 0x1, in_service = 0x2),
[0x5] = (event = TRAMP_LOG_EVENT_NEST_FINISH = 0x0E, irq = TRAMP_NULL_IRQ =
0x0, timestamp = 0x03984FD1, level = TRAMP_LOG_LEVEL_0 = 0x0, in_stack =
0x0, in_service = 0x0)
Besides tramp_log, tramp.table is a table that stores important information (such as ISR and some
debugging data including the last time the IRQ was handled and how many times it has fired,
etc.) about interrupts.
.2 Tramp GPIO log
For GPIO interrupt, tramp_gpio.log provides a log of the past 100 GPIO interrupts.
typedef struct
{
uint32 gpio;
uint32 timestamp;
} tramp_gpio_log_entry_type;
typedef struct
{
uint32 index;
tramp_gpio_log_entry_type entries[MAX_TRAMP_GPIO_LOG_ENTRIES];
} tramp_gpio_log_type;
typedef struct
{
boolean initialized;
tramp_gpio_data_type table[HAL_GPIOINT_NUM];
tramp_handler_type wakeup_isr;
#ifdef FEATURE_TRAMP_LOG
tramp_gpio_log_type log;
No comments:
Post a Comment