#3665 closed enhancement (fixed)

Add low level event recording infrastructure

Reported by: Sebastian Huber Owned by: Sebastian Huber
Priority: normal Milestone: 5.1
Component: lib Version: 5
Severity: normal Keywords:
Cc: Blocked By:
Blocking:

Description

Add low level event recording infrastructure for system and user defined events. The infrastructure should be able to record high frequency events such as

  • SMP lock acquire/release,
  • interrupt entry/exit,
  • thread switches,
  • UMA zone allocate/free,
  • Ethernet packet input/output, etc.

It should allow post-mortem analysis in fatal error handlers, e.g. the last events should be in the record buffer, the newest event overwrites the oldest event. It should be possible to detect record buffer overflows for consumers that expect a continuous stream of events, e.g. to display the system state in real-time.

The framework should support high-end SMP machines (more than 1GHz processor frequency, more than four processors).

The existing capture engine tries to solve this problem, but its performance is not good enough for high-end production systems. The main issues are the variable-size buffers and the use of SMP locks for synchronization. To fix this, the API would change significantly.

Add a new API instead. The implementation should use per-processor data structures and no atomic read-modify-write operations. It is pretty much a per-processor ring buffer for record events.

Use the CPU counter to get the time of events. Combine it with periodic uptime events to synchronize it with CLOCK_REALTIME.

Here is an example of the

/**
 * @brief Produces a record item.
 *
 * @param event The record event without a time stamp for the item.
 * @param data The record data for the item.
 */
void rtems_record_produce( rtems_record_event event, rtems_record_data data );

function PowerPC machine code generated by GCC:

00000000 <rtems_record_produce>:
   0:   7d 00 00 a6     mfmsr   r8
   4:   7c 00 01 46     wrteei  0
   8:   7d 2e 82 a6     mfspr   r9,526
   c:   7d 50 42 a6     mfsprg  r10,0
  10:   81 4a 02 b4     lwz     r10,692(r10)
  14:   55 29 50 2a     rlwinm  r9,r9,10,0,21
  18:   7d 23 1b 78     or      r3,r9,r3
  1c:   81 2a 00 00     lwz     r9,0(r10)
  20:   80 ca 00 08     lwz     r6,8(r10)
  24:   38 e9 00 01     addi    r7,r9,1
  28:   7d 29 30 38     and     r9,r9,r6
  2c:   55 29 18 38     rlwinm  r9,r9,3,0,28
  30:   7d 2a 4a 14     add     r9,r10,r9
  34:   90 69 00 48     stw     r3,72(r9)
  38:   90 89 00 4c     stw     r4,76(r9)
  3c:   7c 20 04 ac     lwsync
  40:   90 ea 00 00     stw     r7,0(r10)
  44:   7d 00 01 06     wrtee   r8
  48:   4e 80 00 20     blr

Just 19 instructions, no branches, no stack frame, no atomic-read-modify-write, just a light weight synchronization to ensure that the consumer reads not half finished items.

Change History (46)

comment:1 Changed on Jan 29, 2019 at 12:57:00 PM by Sebastian Huber <sebastian.huber@…>

In dca6184/rtems:

Add low level event recording support

Add low level event recording infrastructure for system and user
defined events. The infrastructure is able to record high frequency
events such as

  • SMP lock acquire/release,
  • interrupt entry/exit,
  • thread switches,
  • UMA zone allocate/free, and
  • Ethernet packet input/output, etc.

It allows post-mortem analysis in fatal error handlers, e.g. the last
events are in the record buffer, the newest event overwrites the oldest
event. It is possible to detect record buffer overflows for consumers
that expect a continuous stream of events, e.g. to display the system
state in real-time.

The implementation supports high-end SMP machines (more than 1GHz
processor frequency, more than four processors).

Add a new API instead. The implementation uses per-processor data
structures and no atomic read-modify-write operations. It is uses
per-processor ring buffers to record the events.

The CPU counter is used to get the time of events. It is combined with
periodic uptime events to synchronize it with CLOCK_REALTIME.

The existing capture engine tries to solve this problem also, but its
performance is not good enough for high-end production systems. The
main issues are the variable-size buffers and the use of SMP locks for
synchronization. To fix this, the API would change significantly.

Update #3665.

comment:2 Changed on Jan 30, 2019 at 10:32:21 AM by Sebastian Huber <sebastian.huber@…>

In 03cdd5ea/rtems:

record: Add enum value for each event

Update #3665.

comment:3 Changed on Feb 1, 2019 at 8:52:23 AM by Sebastian Huber <sebastian.huber@…>

In d06b195/rtems-docs:

c-user: Add event recording configuration

Update #3665.

comment:4 Changed on Feb 1, 2019 at 8:52:25 AM by Sebastian Huber <sebastian.huber@…>

In 21c4a44/rtems-docs:

user: Add basic event recording documentation

Update #3665.

comment:5 Changed on Mar 12, 2019 at 1:03:10 PM by Sebastian Huber <sebastian.huber@…>

In d91951fb/rtems:

record: Rename internal per-CPU events

Update #3665.

comment:6 Changed on Mar 12, 2019 at 1:03:14 PM by Sebastian Huber <sebastian.huber@…>

In ebb8c28e/rtems:

record: Add system call entry/exit events

This corresponds to the Linux syscall_entry_* and syscall_exit_* events.

Update #3665.

comment:7 Changed on Mar 12, 2019 at 1:03:17 PM by Sebastian Huber <sebastian.huber@…>

In 01a5ced5/rtems:

record: Add more system events

Update #3665.

comment:8 Changed on Aug 20, 2019 at 8:51:11 PM by Sebastian Huber <sebastian.huber@…>

In f9dce02/rtems-tools:

record: New program

Update #3665.

comment:9 Changed on Aug 27, 2019 at 6:47:34 AM by Sebastian Huber <sebastian.huber@…>

In a8af7a14/rtems:

record: Fix thread names on 64-bit targets

Also fixes the thread names on signed char targets.

Update #3665.

comment:10 Changed on Aug 27, 2019 at 6:47:37 AM by Sebastian Huber <sebastian.huber@…>

In e273e7a9/rtems:

record: Add data size to client

This is necessary to get the thread names properly on 32-bit and 64-bit
targets.

Update #3665.

comment:11 Changed on Aug 27, 2019 at 6:52:40 AM by Sebastian Huber <sebastian.huber@…>

In 577f986/rtems-tools:

record: Move per-CPU variables to separate context

Update #3665.

comment:12 Changed on Aug 27, 2019 at 6:52:42 AM by Sebastian Huber <sebastian.huber@…>

In 91d0d1d/rtems-tools:

record: Simplify packet context setup

Update #3665.

comment:13 Changed on Aug 27, 2019 at 6:52:44 AM by Sebastian Huber <sebastian.huber@…>

In e488c98/rtems-tools:

record: Move base context to client context

Update #3665.

comment:14 Changed on Aug 27, 2019 at 6:52:46 AM by Sebastian Huber <sebastian.huber@…>

In 6c4b770/rtems-tools:

record: Add CPU to idle thread names

Update #3665.

comment:15 Changed on Aug 27, 2019 at 6:52:48 AM by Sebastian Huber <sebastian.huber@…>

In 3f45f38/rtems-tools:

record: Add data size to client

This is necessary to get the thread names properly on 32-bit and 64-bit
targets.

Update #3665.

comment:16 Changed on Aug 27, 2019 at 6:52:50 AM by Sebastian Huber <sebastian.huber@…>

In 3c42656/rtems-tools:

record: Support thread names on 32-bit targets

Update #3665.

comment:17 Changed on Aug 28, 2019 at 2:02:53 PM by Sebastian Huber <sebastian.huber@…>

In a2684c2b/rtems:

record: Use BSS section instead of per-CPU data

The .rtemsrwset section is used for the per-CPU data. This section has
loadable content. Place the ring buffers in the BSS section to avoid
large executable image sizes.

Not using the per-CPU data makes it possible to initialize the record
support earlier.

Update #3665.

comment:18 Changed on Aug 28, 2019 at 2:02:56 PM by Sebastian Huber <sebastian.huber@…>

In 3eb8d783/rtems:

record: Introduce <rtems/recordserver.h>

This helps to get rid of the <rtems/rtems/tasks.h> dependency in
<rtems/record.h>.

Update #3665.

comment:19 Changed on Aug 28, 2019 at 2:03:00 PM by Sebastian Huber <sebastian.huber@…>

In 956a2ef/rtems:

record: Add variants for critical sections

Update #3665.

comment:20 Changed on Aug 29, 2019 at 2:02:42 PM by Sebastian Huber <sebastian.huber@…>

In 58bd67b/rtems:

record: Add more system events

Reduce the system dependencies to allow tracing of very low level
functions, for example the interrupt disable/enable.

Introduce general purpose RTEMS_RECORD_CALLER and RTEMS_RECORD_LINE
events.

Update #3665.

comment:21 Changed on Aug 29, 2019 at 2:05:45 PM by Sebastian Huber <sebastian.huber@…>

In b1abc7d/rtems-tools:

record: Synchronize with RTEMS

Update #3665.

comment:22 Changed on Aug 30, 2019 at 7:01:18 AM by Sebastian Huber <sebastian.huber@…>

In d78082c/rtems:

record: Introduce _Record_Drain()

This allows its use in crash dump procedures.

Update #3665.

comment:23 Changed on Aug 30, 2019 at 7:01:22 AM by Sebastian Huber <sebastian.huber@…>

In 11f196d6/rtems:

record: Simplify configuration

Update #3665.

comment:24 Changed on Aug 30, 2019 at 7:01:27 AM by Sebastian Huber <sebastian.huber@…>

In 1e18f64/rtems:

record: Initialize records earlier

The _Record_Initialize() function depends only initialized read-only
data. Call it as the first initialization step to allow tracing of the
complete system initialization.

Update #3665.

comment:25 Changed on Aug 30, 2019 at 9:49:35 AM by Sebastian Huber <sebastian.huber@…>

In 8ace7ead/rtems:

record: Add system events

Add system events to identify the target system. Add system events to
transfer blocks of memory and register sets.

Update #3665.

comment:26 Changed on Aug 30, 2019 at 9:53:09 AM by Sebastian Huber <sebastian.huber@…>

In 67f7638/rtems-tools:

record: Synchronize with RTEMS

Update #3665.

comment:27 Changed on Aug 30, 2019 at 1:03:47 PM by Sebastian Huber <sebastian.huber@…>

In 1c72ad7/rtems:

record: Add system events

Add system events for memory allocation/free.

Update #3665.

comment:28 Changed on Aug 30, 2019 at 5:50:29 PM by Sebastian Huber <sebastian.huber@…>

In f127341/rtems-tools:

record: Synchronize with RTEMS

Update #3665.

comment:29 Changed on Sep 2, 2019 at 5:56:58 AM by Sebastian Huber <sebastian.huber@…>

In e41e9961/rtems:

record: Add system events

Update #3665.

comment:30 Changed on Sep 2, 2019 at 6:14:50 AM by Sebastian Huber <sebastian.huber@…>

In 7cb3a0f/rtems-tools:

record: Synchronize with RTEMS

Update #3665.

comment:31 Changed on Sep 3, 2019 at 1:03:20 PM by Sebastian Huber <sebastian.huber@…>

In e0ac299/rtems-tools:

record: Convert to C++

Formatted with:

clang-format -style=Chromium -i trace/record/record-main-lttng.cc

Update #3665.

comment:32 Changed on Sep 3, 2019 at 1:03:22 PM by Sebastian Huber <sebastian.huber@…>

In a124bdb/rtems-tools:

record: Add Client base class

Update #3665.

comment:33 Changed on Sep 4, 2019 at 11:48:07 AM by Sebastian Huber <sebastian.huber@…>

In fb5b75a/rtems-tools:

record: Use exceptions

Update #3665.

comment:34 Changed on Sep 4, 2019 at 11:48:10 AM by Sebastian Huber <sebastian.huber@…>

In ce308fa/rtems-tools:

record: Only create necessary stream files

Rename the files to stream_* so that they appear after the metadata
file. This makes it easier to open a new trace in Trace Compass.

Update #3665.

comment:35 Changed on Sep 4, 2019 at 11:48:12 AM by Sebastian Huber <sebastian.huber@…>

In ff942d5/rtems-tools:

record: Simplify CopyThreadName?()

Update #3665.

comment:36 Changed on Sep 4, 2019 at 11:48:15 AM by Sebastian Huber <sebastian.huber@…>

In 0df7b2f/rtems-tools:

record: Add support for interrupt handlers

Update #3665.

comment:37 Changed on Sep 4, 2019 at 11:48:17 AM by Sebastian Huber <sebastian.huber@…>

In 58edee9/rtems-tools:

record: Simplify content and packet size

Update #3665.

comment:38 Changed on Sep 4, 2019 at 12:03:39 PM by Sebastian Huber <sebastian.huber@…>

In 876ace8/rtems-tools:

record: Simplify command line options

Update #3665.

comment:39 Changed on Sep 4, 2019 at 12:43:10 PM by Sebastian Huber <sebastian.huber@…>

In 71929ce/rtems-tools:

record: Add limit option

Update #3665.

comment:40 Changed on Sep 5, 2019 at 8:50:08 AM by Sebastian Huber <sebastian.huber@…>

In 0b12f00/rtems-tools:

record: Clean up metadata

Update #3665.

comment:41 Changed on Sep 5, 2019 at 8:50:26 AM by Sebastian Huber <sebastian.huber@…>

In 07829ca/rtems-tools:

record: Use C++ header files and namespace std

Update #3665.

comment:42 Changed on Sep 5, 2019 at 8:50:28 AM by Sebastian Huber <sebastian.huber@…>

In f8f91d6/rtems-tools:

record: Add generic record events

Update #3665.

comment:43 Changed on Sep 9, 2019 at 5:05:59 AM by Sebastian Huber <sebastian.huber@…>

In c331bdc/rtems:

record: Allow tracing of ISR disable/enable

Directly use the CPU port API in boot_card() to allow tracing of the
higher level interrupt disable/enable routines, e.g.
_ISR_Local_disable() and _ISR_Local_enable(). Currently, there is no
configuration option to enable this. Below is a patch. It may be used
to investigate some nasty low level bugs in the system.

Update #3665.

diff --git a/cpukit/include/rtems/score/isrlevel.h b/cpukit/include/rtems/score/isrlevel.h
index c42451d010..46d361ddc2 100644
--- a/cpukit/include/rtems/score/isrlevel.h
+++ b/cpukit/include/rtems/score/isrlevel.h
@@ -40,6 +40,10 @@ extern "C" {

*/

typedef uint32_t ISR_Level;

+uint32_t rtems_record_interrupt_disable( void );
+
+void rtems_record_interrupt_enable( uint32_t level );
+

/

  • @brief Disables interrupts on this processor. *

@@ -56,8 +60,7 @@ typedef uint32_t ISR_Level;

*/

#define _ISR_Local_disable( _level ) \

do { \

  • _CPU_ISR_Disable( _level ); \
  • RTEMS_COMPILER_MEMORY_BARRIER(); \

+ _level = rtems_record_interrupt_disable(); \

} while (0)

/

@@ -72,10 +75,7 @@ typedef uint32_t ISR_Level;

  • _ISR_Local_disable(). */

#define _ISR_Local_enable( _level ) \

  • do { \
  • RTEMS_COMPILER_MEMORY_BARRIER(); \
  • _CPU_ISR_Enable( _level ); \
  • } while (0)

+ rtems_record_interrupt_enable( _level )

/

  • @brief Temporarily enables interrupts on this processor.

@@ -98,9 +98,8 @@ typedef uint32_t ISR_Level;

*/

#define _ISR_Local_flash( _level ) \

do { \

  • RTEMS_COMPILER_MEMORY_BARRIER(); \
  • _CPU_ISR_Flash( _level ); \
  • RTEMS_COMPILER_MEMORY_BARRIER(); \

+ rtems_record_interrupt_enable( _level ); \
+ _level = rtems_record_interrupt_disable(); \

} while (0)

/

comment:44 Changed on Oct 1, 2019 at 7:55:23 AM by Sebastian Huber <sebastian.huber@…>

In c1eb577/rtems:

libtests/record01: Fix test failure

Update #3665.

comment:45 Changed on Oct 2, 2019 at 4:38:31 AM by Sebastian Huber <sebastian.huber@…>

In a314544a/rtems:

record: Add wrappers for malloc() functions

Introduce new library librtemsrecordwrap.a which contains wrappers for
operating system functions which produce entry/exit events.

The wrappers can be selected during link time via the GNU ld --wrap
option.

Update #3665.

comment:46 Changed on Dec 19, 2019 at 9:26:09 AM by Sebastian Huber

Resolution: fixed
Status: assignedclosed

All the basic functionality is integrated. New features/bugs should use new tickets.

Note: See TracTickets for help on using tickets.