fix(global, log): fix esp_log(_early)_timestamp readings after startup by correct the CCOUNT register when switching CPU clock.

TW#13332, Closes #700

components/esp32/clk.c

@@ -27,6 +27,7 @@
 #include "soc/rtc_cntl_reg.h"
 #include "soc/dport_reg.h"
 #include "soc/i2s_reg.h"
+#include "xtensa/core-macros.h"
 
 /* Number of cycles to wait from the 32k XTAL oscillator to consider it running.
  * Larger values increase startup delay. Smaller values may cause false positive
@@ -35,6 +36,8 @@
 #define XTAL_32K_DETECT_CYCLES  32
 #define SLOW_CLK_CAL_CYCLES     CONFIG_ESP32_RTC_CLK_CAL_CYCLES
 
+#define MHZ (1000000)
+
 static void select_rtc_slow_clk(rtc_slow_freq_t slow_clk);
 
 static const char* TAG = "clk";
@@ -77,7 +80,14 @@ void esp_clk_init(void)
     // Wait for UART TX to finish, otherwise some UART output will be lost
     // when switching APB frequency
     uart_tx_wait_idle(CONFIG_CONSOLE_UART_NUM);
+    
+    uint32_t freq_before = rtc_clk_cpu_freq_value(rtc_clk_cpu_freq_get()) / MHZ ;
+    
     rtc_clk_cpu_freq_set(freq);
+
+    // Re calculate the ccount to make time calculation correct. 
+    uint32_t freq_after = CONFIG_ESP32_DEFAULT_CPU_FREQ_MHZ;
+    XTHAL_SET_CCOUNT( XTHAL_GET_CCOUNT() * freq_after / freq_before );
 }
 
 void IRAM_ATTR ets_update_cpu_frequency(uint32_t ticks_per_us)

components/log/log.c

@@ -310,10 +310,13 @@ static inline void heap_swap(int i, int j)
 #define ATTR
 #endif // BOOTLOADER_BUILD
 
+//the variable defined in ROM is the cpu frequency in MHz.
+//as a workaround before the interface for this variable
+extern uint32_t g_ticks_per_us_pro;
 
 uint32_t ATTR esp_log_early_timestamp()
 {
-    return xthal_get_ccount() / (CPU_CLK_FREQ_ROM / 1000);
+    return xthal_get_ccount() / (g_ticks_per_us_pro * 1000);
 }
 
 #ifndef BOOTLOADER_BUILD
@@ -324,7 +327,7 @@ uint32_t IRAM_ATTR esp_log_timestamp()
         return esp_log_early_timestamp();
     }
     static uint32_t base = 0;
-    if (base == 0) {
+    if (base == 0 && xPortGetCoreID() == 0) {
         base = esp_log_early_timestamp();
     }
     return base + xTaskGetTickCount() * (1000 / configTICK_RATE_HZ);

components/soc/esp32/rtc_clk.c

@@ -29,6 +29,7 @@
 #include "i2c_rtc_clk.h"
 #include "soc_log.h"
 #include "sdkconfig.h"
+#include "xtensa/core-macros.h"
 
 
 #define MHZ (1000000)
@@ -510,6 +511,8 @@ uint32_t rtc_clk_apb_freq_get()
 
 void rtc_clk_init(rtc_clk_config_t cfg)
 {
+    rtc_cpu_freq_t cpu_source_before = rtc_clk_cpu_freq_get();
+    
     /* If we get a TG WDT system reset while running at 240MHz,
      * DPORT_CPUPERIOD_SEL register will be reset to 0 resulting in 120MHz
      * APB and CPU frequencies after reset. This will cause issues with XTAL
@@ -569,6 +572,11 @@ void rtc_clk_init(rtc_clk_config_t cfg)
     rtc_clk_apb_freq_update(xtal_freq * MHZ);
     /* Set CPU frequency */
     rtc_clk_cpu_freq_set(cfg.cpu_freq);
+    
+    /* Re-calculate the ccount to make time calculation correct. */    
+    uint32_t freq_before = rtc_clk_cpu_freq_value(cpu_source_before) / MHZ;
+    uint32_t freq_after = rtc_clk_cpu_freq_value(cfg.cpu_freq) / MHZ;
+    XTHAL_SET_CCOUNT( XTHAL_GET_CCOUNT() * freq_after / freq_before );
 
     /* Slow & fast clocks setup */
     if (cfg.slow_freq == RTC_SLOW_FREQ_32K_XTAL) {