diff --git a/app_timer2.c b/app_timer2_logs.c index dfafbcb6..c12ea778 100644 --- a/app_timer2.c +++ b/app_timer2_logs.c @@ -150,6 +150,29 @@ static void scheduled_timeout_handler(void * p_event_data, uint16_t event_size) } #endif +static inline void sortlist_dump(void) +{ + uint64_t prev_end_val = 0; + uint32_t timer_idx = 0; + app_timer_t const * p_next = (app_timer_t const *)m_app_timer_sortlist.p_cb->p_head; + while (p_next) + { + NRF_LOG_DEBUG("%d) p_t=%p cc=0x%x", timer_idx++, p_next, p_next->end_val); + if (p_next->end_val < prev_end_val) + { + NRF_LOG_DEBUG("WRONG ORDER"); + } + + if (p_next->end_val != APP_TIMER_IDLE_VAL) + { + prev_end_val = p_next->end_val; + } + + p_next = (app_timer_t const *)p_next->list_item.p_next; + } + NRF_LOG_DEBUG("END OF DUMP"); +} + /** * @brief Function called on timer expiration * If end value is not reached it is assumed that it was partial expiration and time is put back @@ -188,7 +211,7 @@ static bool timer_expire(app_timer_t * p_timer) scheduled_timeout_handler); APP_ERROR_CHECK(err_code); #else - NRF_LOG_DEBUG("Timer expired (context: %d)", (uint32_t)p_timer->p_context) + NRF_LOG_DEBUG("Timer expired (context: %d), p_timer=%p", (uint32_t)p_timer->p_context, p_timer) p_timer->handler(p_timer->p_context); #endif CRITICAL_REGION_ENTER(); @@ -206,13 +229,16 @@ static bool timer_expire(app_timer_t * p_timer) if (cont) { + NRF_LOG_DEBUG("Timer rescheduled p_timer=%p to CC: 0x%x", p_timer, p_timer->end_val) nrf_sortlist_add(&m_app_timer_sortlist, &p_timer->list_item); + sortlist_dump(); ret = true; } } else if (!APP_TIMER_IS_IDLE(p_timer)) { nrf_sortlist_add(&m_app_timer_sortlist, &p_timer->list_item); + sortlist_dump(); ret = true; } } @@ -321,7 +347,7 @@ static void on_compare_evt(drv_rtc_t const * const p_instance) ASSERT(app_timer_cnt_diff_compute(drv_rtc_counter_get(p_instance), drv_rtc_compare_get(p_instance, 0)) < APP_TIMER_SAFE_WINDOW); - NRF_LOG_INST_DEBUG(mp_active_timer->p_log, "Compare EVT"); + NRF_LOG_INST_DEBUG(mp_active_timer->p_log, "Compare EVT p_timer=%p at CC=0x%x", mp_active_timer, NRF_RTC1->COUNTER, mp_active_timer->end_val); UNUSED_RETURN_VALUE(timer_expire(mp_active_timer)); mp_active_timer = NULL; } @@ -379,8 +405,10 @@ static void rtc_update(drv_rtc_t const * const p_instance) rtc_reconf = true; if (!APP_TIMER_IS_IDLE(mp_active_timer)) { - NRF_LOG_INST_DEBUG(mp_active_timer->p_log, "Timer preempted."); + NRF_LOG_INST_DEBUG(mp_active_timer->p_log, "Timer preempted: p_timer=%p, end_val=0x%x", mp_active_timer, mp_active_timer->end_val); + NRF_LOG_INST_DEBUG(mp_active_timer->p_log, "Preempted by: p_timer=%p, end_val=0x%x", p_next, p_next->end_val); nrf_sortlist_add(&m_app_timer_sortlist, &mp_active_timer->list_item); + sortlist_dump(); } } @@ -388,7 +416,8 @@ static void rtc_update(drv_rtc_t const * const p_instance) { bool rerun; p_next = sortlist_pop(); - NRF_LOG_INST_DEBUG(p_next->p_log, "Activating timer (CC:%d/%08x).", p_next->end_val, p_next->end_val); + NRF_LOG_INST_DEBUG(p_next->p_log, "Activating timer (CC:0x%x), p_timer=%p.", p_next->end_val, p_next); + sortlist_dump(); if (rtc_schedule(p_next, &rerun)) { if (!APP_TIMER_KEEPS_RTC_ACTIVE && (mp_active_timer == NULL)) @@ -439,6 +468,7 @@ static void timer_req_process(drv_rtc_t const * const p_instance) while (p_req) { + NRF_LOG_INFO("Processing p_timer=%p", p_req->p_timer); switch (p_req->type) { case TIMER_REQ_START: @@ -455,8 +485,9 @@ static void timer_req_process(drv_rtc_t const * const p_instance) if (!APP_TIMER_IS_IDLE(p_req->p_timer)) { nrf_sortlist_add(&m_app_timer_sortlist, &(p_req->p_timer->list_item)); - NRF_LOG_INST_DEBUG(p_req->p_timer->p_log,"Start request (expiring at %d/0x%08x).", - p_req->p_timer->end_val, p_req->p_timer->end_val); + NRF_LOG_INST_DEBUG(p_req->p_timer->p_log,"Start request (expiring at %d/0x%08x). p_timer=%p", + p_req->p_timer->end_val, p_req->p_timer->end_val, p_req->p_timer); + sortlist_dump(); } break; case TIMER_REQ_STOP: @@ -466,13 +497,15 @@ static void timer_req_process(drv_rtc_t const * const p_instance) } else { + NRF_LOG_DEBUG("Removed p_timer=%p from list", p_req->p_timer); bool found = nrf_sortlist_remove(&m_app_timer_sortlist, &(p_req->p_timer->list_item)); if (!found) { NRF_LOG_INFO("Timer not found on sortlist (stopping expired timer)."); } } - NRF_LOG_INST_DEBUG(p_req->p_timer->p_log,"Stop request."); + NRF_LOG_INST_DEBUG(p_req->p_timer->p_log,"Stop request, p_timer=%p", p_req->p_timer); + sortlist_dump(); break; case TIMER_REQ_STOP_ALL: sorted_list_stop_all(); @@ -496,6 +529,7 @@ static void timer_req_process(drv_rtc_t const * const p_instance) #endif /* APP_TIMER_WITH_PROFILER */ p_req = nrf_atfifo_item_get(m_req_fifo, &fifo_ctx); } + NRF_LOG_INFO("END OF PROCESSING"); } static void rtc_irq(drv_rtc_t const * const p_instance) @@ -551,7 +585,9 @@ static ret_code_t timer_req_schedule(app_timer_req_type_t type, app_timer_t * p_ p_req->p_timer = p_timer; if (nrf_atfifo_item_put(m_req_fifo, &fifo_ctx)) { + NRF_LOG_INFO("Proc trigger %d for p_timer=%p, handler=%p, end_val=0x%x", type, p_timer, p_timer->handler, p_timer->end_val); timer_request_proc_trigger(); + NRF_LOG_INFO("RTC1 IRQ pending: %d", NVIC_GetPendingIRQ(RTC1_IRQn)); } else { @@ -656,6 +692,7 @@ ret_code_t app_timer_start(app_timer_t * p_timer, uint32_t timeout_ticks, void * ret_code_t app_timer_stop(app_timer_t * p_timer) { + NRF_LOG_INFO("app_timer_stop: p_timer=%p", p_timer); ASSERT(p_timer); app_timer_t * p_t = (app_timer_t *) p_timer;