{"id":8530,"date":"2023-10-18T08:43:51","date_gmt":"2023-10-18T15:43:51","guid":{"rendered":"https:\/\/visualgdb.com\/w\/?p=8530"},"modified":"2023-10-18T08:43:51","modified_gmt":"2023-10-18T15:43:51","slug":"using-backtrack-tracing-to-debug-intermittent-problems","status":"publish","type":"post","link":"https:\/\/visualgdb.com\/tutorials\/tracing\/embedded\/traceback\/","title":{"rendered":"Using Backtrack Tracing to Debug Intermittent Problems"},"content":{"rendered":"

This tutorial shows how to use Live Tracing<\/a> in the the circular buffer (backtrack) mode to record what happened just before a rarely occurring problem without having to slow down the target and capture its entire program flow.<\/p>\n

We will create a basic application using 2 FreeRTOS threads to trigger a race condition, will create tracepoints in the relevant parts of the code, and then once the problem triggers, will use the recorded data to step back in time and see what happened just before the crash.<\/p>\n

    \n
  1. Start Visual Studio and open the VisualGDB Embedded Project Wizard:\"\"<\/a><\/li>\n
  2. Enter the name for the new project and the directory where you would like to create it: \"\"<\/a><\/li>\n
  3. Proceed with the default project type (Embedded Application -> Advanced CMake): \"\"<\/a><\/li>\n
  4. Select the device you would like to target: \"\"<\/a><\/li>\n
  5. Pick the “LEDBlink (FreeRTOS)”<\/strong> template and click “Next” to go to the debug settings page: \"\"<\/a><\/li>\n
  6. Select the debug settings matching your setup, make sure the software tracing is enabled and click “Finish” to generate the project: \"\"<\/a><\/li>\n
  7. Once the project is created, replace the contents of LED_Thread1()<\/strong> and LED_Thread2()<\/strong> functions with the following code:\n
    volatile int g_Counter1, g_Counter2, g_Sum;\r\n\r\nstatic void LED_Thread1(void const *argument)\r\n{\r\n    for (;;)\r\n    {\r\n    \tint tmp = g_Counter1;\r\n    \tg_Counter1 = tmp + 1;\r\n    \ttmp = g_Sum;\r\n    \tg_Sum = tmp + 1;\r\n    }\r\n}\r\n\r\nstatic void LED_Thread2(void const *argument)\r\n{\r\n    for (;;)\r\n    {\r\n        int tmp = g_Counter2;\r\n    \tg_Counter2 = tmp + 1;\r\n    \ttmp = g_Sum;\r\n    \tg_Sum = tmp + 1;\r\n    }\r\n}<\/pre>\n
    \"\"<\/a><\/li>\n
  8. Each thread increments its own counter (g_Counter1<\/strong>\/g_Counter2<\/strong>) and a shared counter called g_Sum<\/strong>. Because of the race condition, the value of g_Sum<\/strong> will be drifting below the sum of g_Counter1<\/strong> + g_Counter2. <\/strong>Try running the program for some time and checking the difference expression: g_Counter 1 + g_Counter2 – g_Sum<\/strong>:\"\"<\/a>Note that it would happen even when using the “g_CounterX++<\/strong>” syntax, but we used explicit reading and writing for clarity.<\/li>\n
  9. Set tracepoints on each of the 4 lines in each thread and configure them to capture the values read in each line. VisualGDB will manage to capture them, however most of the events will be dropped to avoid slowing down the target:\"\"<\/a><\/li>\n
  10. Add a check to both threads that will trigger a breakpoint if the values of g_Sum<\/strong> and the counters drift away too far:\n
        \tif (((g_Counter1 + g_Counter2) - g_Sum) > 1)\r\n        \tasm(\"bkpt 255\");<\/pre>\n
    Note how the last event recorded via regular tracing will contain an outdated value of g_Sum<\/strong>. This happens because tracing every line of a tight loop creates a lot of tracing data (megabytes per second) and the SWD debugger would not keep up with reading it:\"\"<\/a><\/li>\n
  11. Go to the VisualGDB project Properties and switch the software tracing mode to “Overwrite oldest events”: \"\"<\/a>This way, VisualGDB will keep writing the trace into a circular buffer inside the target and will never wait for the debugger to read it.<\/li>\n
  12. Once a breakpoint triggers, VisualGDB will read the data backwards and recover the last events recorded in it. The data in the last recorded event will match the variable values observed via Watch:\"\"<\/a><\/li>\n
  13. Use the navigation buttons to walk back to the previous events and see what happened before the breakpoint got triggered:\"\"<\/a>You will see that just before the failing check (when g_Sum<\/strong> was 21<\/strong>), Thread2<\/strong> set it to 40 + 1<\/strong>.<\/li>\n
  14. Click on the “21 events” label near the g_Sum<\/strong> assignment in Thread1<\/strong>. VisualGDB will load the last event recorded there (#103), showing that tmp<\/strong> had a value of 20 back then:\"\"<\/a>This explains what exactly happened before the crash:\n
      \n
    1. LED_Thread1<\/strong> started setting g_Sum<\/strong> to 21 <\/strong>[event #103].<\/li>\n
    2. FreeRTOS switched to LED_Thread2.<\/strong><\/li>\n
    3. LED_Thread2<\/strong> ran a few iterations, advancing sum all the way to 41 [event #207].<\/li>\n
    4. FreeRTOS switched back to LED_Thread1<\/strong>.<\/li>\n
    5. LED_Thread1<\/strong> finished writing 21 to g_Sum<\/strong>, effectively rolling it back by 20.<\/li>\n<\/ol>\n<\/li>\n
    6. You can easily collect the current thread value and thread switches via Live Tracing. Select all tracepoints in the Tracepoints window and check pxCurrentTCB inside the view to begin tracing it:\"\"<\/a><\/li>\n
    7. Add another tracepoint in tasks.c<\/strong> on the traceTASK_SWITCHED_IN()<\/strong> line inside vTaskSwitchContext()<\/strong>:\"\"<\/a><\/li>\n
    8. VisualGDB will now show how pxCurrentTCB<\/strong> got changed between the events, and will even capture the exact moment of the switch:\"\"<\/a><\/li>\n
    9. If you selected to trace additional fields of pxCurrentTCB<\/strong> in the task switch tracepoint, you can see the state of the thread that was just switching in (e.g. its stack pointer, number of held mutexes, etc): \"\"<\/a>Live Tracing is very flexible – you can record the state of any object (e.g. custom mutex or some variables in your code) at any point in time (thread switches, interrupts, any other function calls or source lines being executed) and analyze it when you need it.<\/li>\n<\/ol>\n","protected":false},"excerpt":{"rendered":"
      This tutorial shows how to use Live Tracing in the the circular buffer (backtrack) mode to record what happened just<\/p>\n","protected":false},"author":1,"featured_media":0,"comment_status":"closed","ping_status":"closed","sticky":false,"template":"","format":"standard","meta":{"footnotes":""},"categories":[247],"tags":[67,248,204,61],"_links":{"self":[{"href":"https:\/\/visualgdb.com\/w\/wp-json\/wp\/v2\/posts\/8530"}],"collection":[{"href":"https:\/\/visualgdb.com\/w\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/visualgdb.com\/w\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/visualgdb.com\/w\/wp-json\/wp\/v2\/users\/1"}],"replies":[{"embeddable":true,"href":"https:\/\/visualgdb.com\/w\/wp-json\/wp\/v2\/comments?post=8530"}],"version-history":[{"count":2,"href":"https:\/\/visualgdb.com\/w\/wp-json\/wp\/v2\/posts\/8530\/revisions"}],"predecessor-version":[{"id":8560,"href":"https:\/\/visualgdb.com\/w\/wp-json\/wp\/v2\/posts\/8530\/revisions\/8560"}],"wp:attachment":[{"href":"https:\/\/visualgdb.com\/w\/wp-json\/wp\/v2\/media?parent=8530"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/visualgdb.com\/w\/wp-json\/wp\/v2\/categories?post=8530"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/visualgdb.com\/w\/wp-json\/wp\/v2\/tags?post=8530"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}