OVMS3-idf/examples/system/app_trace_to_host

Example: Application Level Tracing - Logging to Host (app_trace_to_host)

(See the README.md file in the upper level 'examples' directory for more information about examples.)

Overview

This example will show how to perform high speed logging by redirecting the log messages to a host instead of UART.

For more description of logging to host please refer to ESP-IDF Programming Guide, section Application Level Tracing library. The following example provides practical implementation of this functionality.

Use Case

Debugging of time critical functions may not work as desired if log messages are sent through the UART port. Printing out the logs may considerably slow down tested function to the point where it will not operate as expected.

Let's consider a case we are testing implementation of zero level crossing detection for a 50 Hz signal with ESP32's ADC.

We will start by checking if we can read ADC, what is the signal level and how many samples can be collected over 20 ms period by using a code snippet below:

int sampling_period = 20;
int i = 0;
uint32_t sampling_start =  esp_log_timestamp();  //this clock counts miliseconds
do {
    ESP_LOGI(TAG, "Sample:%d, Value:%d", ++i, adc1_get_raw(ADC1_TEST_CHANNEL));
} while (esp_log_timestamp() - sampling_start < sampling_period);

Above code is sampling ADC in a loop continuously for 20 ms of time to collect one full period of 50 Hz signal (use 17 ms for 60 Hz signal), and printing out results. If you run this code, result will be likely as below:

I (4309) example: Sample:1, Value:2224
I (4309) example: Sample:2, Value:840
I (4309) example: Sample:3, Value:3503
I (4319) example: Sample:4, Value:27
I (4319) example: Sample:5, Value:4095

As you see we were able to collect only five samples. This seems rather not adequate for zero crossing detection.

We can remove ESP_LOGI() line and sample much faster, but then will not be able to see the values. To see the values we would need to save them in the memory and print out later.

Instead of saving samples to memory, a simple and compelling solution to this issue is sending logs to a host over a JTAG interface. This works much faster than UART. To do so, we need to redirect log messages to JTAG by calling the following function before ESP_LOGx line:

esp_log_set_vprintf(esp_apptrace_vprintf);

Once time critical messages are sent out, we can redirect ESP_LOGx back back to the UART by adding extra two lines of code.

esp_log_set_vprintf(vprintf);
esp_apptrace_flush(ESP_APPTRACE_DEST_TRAX, 100000);

Note command esp_apptrace_flush() used to empty buffer with pending messages to the host.

If checking the log received by the host, we will see over 400 samples collected!

...
I (59379) example: Sample:424, Value:298
I (59379) example: Sample:425, Value:345
I (59379) example: Sample:426, Value:386
I (59379) example: Sample:427, Value:432
I (61409) example: Sample:1, Value:2653

How to use example

Hardware Required

To run this example, you need an ESP32 dev board (e.g. ESP-WROVER-KIT) which integrates an on-board JTAG adapter. ESP32 core board (e.g. ESP32-DevKitC) can also work as long as you connect it to an external JTAG adapter (e.g. FT2232H, J-LINK). For convenience, here we will take the ESP-WROVER-KIT for example.

Pin Assignment:

Note: Connect 50 / 60 Hz sinusoidal signal to ADC1_CHANNEL_6 / GPIO34. The signal range should be from 0V to max 3.1V. Optionally you can bridge GPIO34 with DAC_CHANNEL_1 / GPIO25.

DAC Output	ADC Input
Channel1 (GPIO25)	Channel6 (GPIO34)

Extra Connections:

1. Connect JTAG interface to ESP32 board, power up both JTAG and ESP32. For details about how to set up JTAG interface, please see JTAG Debugging.

2. After connecting JTAG interface, you need to Run OpenOCD. If you are using the Binary Distribution of OpenOCD and one of versions of ESP-WROVER-KIT, respective command line will look as follows:

   cd ~/esp/openocd-esp32
   bin/openocd -s share/openocd/scripts -f interface/ftdi/esp32_devkitj_v1.cfg -f board/esp-wroom-32.cfg
   

3. Open a separate terminal window and run telnet by entering:

   telnet localhost 4444
   

Configure the project

Enter make menuconfig if you are using GNU Make based build system or enter idf.py menuconfig if you are using CMake based build system. Then go into Example Configuration menu.

• By default, the DAC will generate 130 Hz signal within 0V..3.1V. To get 50Hz, you need to set non-standard driver of RTC 8MHz clock to lower minimum CW (Cosine Waveform) generator's frequency in Set custom RTC 8 MHz clock divider to lower CW frequency.

Note To enable application tracing, go to Component config > Application Level Tracing and select (X) Trace memory. (By default, this option has been switched on in the sdkconfig.defaults).

Build, Flash and Run

1. Enter make -j4 flash monitor if you are using GNU Make based build system or enter idf.py build flash monitor if you are using CMake based build system. (To exit the serial monitor, type Ctrl-].) See the Getting Started Guide for full steps to configure and use ESP-IDF to build projects.

2. In the telnet session window, run the following command. This command will collect 9000 bytes of log data and save them to adc.log file in ~/esp/openocd-esp32 folder.

   esp32 apptrace start file://adc.log 0 9000 5 0 0
   

3. Decode and print out retrieved log file by executing:

   $IDF_PATH/tools/esp_app_trace/logtrace_proc.py ~/esp/openocd-esp32/adc.log ~/esp/app_trace_to_host/build/app_trace_to_host_test.elf
   

   This should provide a similar output:

   Parse trace file '/user-home/esp/openocd-esp32/adc.log'...
   Unprocessed 7 bytes of log record args!
   Parsing completed.
   ====================================================================
   I (59369) example: Sample:1, Value:3717
   I (59369) example: Sample:2, Value:3647
   I (59369) example: Sample:3, Value:3575
   I (59369) example: Sample:4, Value:3491
   ...
   
   I (59379) example: Sample:398, Value:78
   I (59379) example: Sample:399, Value:58
   I (59379) example: Sample:400, Value:22
   I (59379) example: Sample:401, Value:14
   I (59379) example: Sample:402, Value:0
   I (59379) example: Sample:403, Value:0
   I (59379) example: Sample:404, Value:0
   I (59379) example: Sample:405, Value:0
   I (59379) example: Sample:406, Value:0
   I (59379) example: Sample:407, Value:0
   I (59379) example: Sample:408, Value:0
   I (59379) example: Sample:409, Value:0
   I (59379) example: Sample:410, Value:0
   I (59379) example: Sample:411, Value:0
   I (59379) example: Sample:412, Value:0
   I (59379) example: Sample:413, Value:0
   I (59379) example: Sample:414, Value:16
   I (59379) example: Sample:415, Value:32
   I (59379) example: Sample:416, Value:40
   I (59379) example: Sample:417, Value:74
   I (59379) example: Sample:418, Value:89
   I (59379) example: Sample:419, Value:113
   I (59379) example: Sample:420, Value:160
   I (59379) example: Sample:421, Value:192
   I (59379) example: Sample:422, Value:221
   I (59379) example: Sample:423, Value:256
   I (59379) example: Sample:424, Value:298
   I (59379) example: Sample:425, Value:345
   I (59379) example: Sample:426, Value:386
   I (59379) example: Sample:427, Value:432
   I (61409) example: Sample:1, Value:2653
   
   ====================================================================
   
   Log records count: 428
   

This is the log we have been looking for, complete with timestamps as if printed to UART, but almost two orders of magnitude faster.

Example Output

Check the full example code app_trace_to_host that combines both tests above and runs them in a loop showing instantly the number of samples collected:

I (4289) example: Sampling ADC and sending data to the host...
I (4309) example: Collected 427 samples in 20 ms.

I (4309) example: Sampling ADC and sending data to the UART...
I (4309) example: Sample:1, Value:2224
I (4309) example: Sample:2, Value:840
I (4309) example: Sample:3, Value:3503
I (4319) example: Sample:4, Value:27
I (4319) example: Sample:5, Value:4095
I (4329) example: Collected 5 samples in 20 ms.

note Above result is generated under CPU running at 240 MHz.

Conclusion

With this example code we have demonstrated powerful functionality of logging to host with JTAG interface. With standard UART communication baud rate setting of 115200, printing out a single line of a log message takes about 4 ms. This is also the maximum period we can sequentially execute other tasks in between. By providing the same logging over JTAG, we will be able to improve performance of this process over 80 times.

Troubleshooting

1. I can not flash new firmware when OpenOCD is connected to ESP32.
   • One likely cause would be that you set wrong SPI flash voltage when you start OpenOCD. Suppose you're working with an ESP32 board / module which has a 3.3V powered SPI flash, but you select board/esp32-wrover.cfg configuration file when start OpenOCD. In this situation, you might not be able to flash ESP32 when OpenOCD is connected. So make sure what the working voltage of the SPI flash is. Currently, for 1.8V flash, we'd like to suggest using board/esp32-wrover.cfg and for 3.3V flash, using board/esp-wroom-32.cfg. For more information about it, please refer to ESP32 Modules and Boards and Set SPI Flash Voltage.

(For any technical queries, please open an issue on GitHub. We will get back to you as soon as possible.)