Merge pull request #959 from om jphickey/fix-957-consoletask-async-op…

…tion

Fix #957, move async console option

default_config.cmake

@@ -180,6 +180,31 @@ set(OSAL_CONFIG_DEBUG_PRINTF                    FALSE
     CACHE BOOL "Controls inclusion of OS_DEBUG statements in the code"
 )
 
+#
+# OS_CONFIG_CONSOLE_ASYNC
+# ----------------------------------
+#
+# Controls whether the console device writes (OS_printf) will be deferred
+# to a separate utility task or handled directly by the calling task.
+#
+# If set FALSE, the utility task WILL NOT be spawned, and all OS_printf()
+# calls will be synchronously written to the console device.
+#
+# If set TRUE, an extra utility task WILL be spawned, and the data from
+# all OS_printf() calls will be written to an output queue which is then
+# transferred to the console device by the utility task.
+#
+# When this is TRUE (default), it may improve real time performance by not
+# requiring the caller to delay on a potentially slow console device output.
+#
+# However decoupling in this manner requires creation of an extra task and
+# stack to handle the output, and a side effect is that the OS_printf() output
+# can become decoupled from the event/task where it actually occurred, or
+# messages might appear in a different order than they originally occurred.
+#
+set(OSAL_CONFIG_CONSOLE_ASYNC                   TRUE
+    CACHE BOOL "Controls spawning of a separate utility task for OS_printf"
+)
 
 #############################################
 # Resource Limits for the OS API

osconfig.h.in

@@ -44,6 +44,7 @@
 #cmakedefine OSAL_CONFIG_INCLUDE_SHELL
 #cmakedefine OSAL_CONFIG_DEBUG_PRINTF
 #cmakedefine OSAL_CONFIG_DEBUG_PERMISSIVE_MODE
+#cmakedefine OSAL_CONFIG_CONSOLE_ASYNC
 
 #cmakedefine OSAL_CONFIG_BUGCHECK_DISABLE
 #cmakedefine OSAL_CONFIG_BUGCHECK_STRICT

src/os/posix/inc/os-impl-console.h

@@ -36,7 +36,6 @@
 /* Console device */
 typedef struct
 {
-    bool  is_async;
     sem_t data_sem;
 } OS_impl_console_internal_record_t;
 

src/os/posix/src/os-impl-console.c

@@ -68,16 +68,9 @@ void OS_ConsoleWakeup_Impl(const OS_object_token_t *token)
 
     local = OS_OBJECT_TABLE_GET(OS_impl_console_table, *token);
 
-    if (local->is_async)
-    {
-        /* post the sem for the utility task to run */
-        sem_post(&local->data_sem);
-    }
-    else
-    {
-        /* output directly */
-        OS_ConsoleOutput_Impl(token);
-    }
+    /* post the sem for the utility task to run */
+    sem_post(&local->data_sem);
+
 } /* end OS_ConsoleWakeup_Impl */
 
 /*----------------------------------------------------------------
@@ -121,18 +114,19 @@ static void *OS_ConsoleTask_Entry(void *arg)
 int32 OS_ConsoleCreate_Impl(const OS_object_token_t *token)
 {
     OS_impl_console_internal_record_t *local;
+    OS_console_internal_record_t *     console;
     pthread_t                          consoletask;
     int32                              return_code;
     OS_VoidPtrValueWrapper_t           local_arg = {0};
 
-    local = OS_OBJECT_TABLE_GET(OS_impl_console_table, *token);
+    console = OS_OBJECT_TABLE_GET(OS_console_table, *token);
+    local   = OS_OBJECT_TABLE_GET(OS_impl_console_table, *token);
 
     if (token->obj_idx == 0)
     {
-        return_code     = OS_SUCCESS;
-        local->is_async = OS_CONSOLE_ASYNC;
+        return_code = OS_SUCCESS;
 
-        if (local->is_async)
+        if (console->IsAsync)
         {
             if (sem_init(&local->data_sem, 0, 0) < 0)
             {

src/os/rtems/inc/os-impl-console.h

@@ -36,7 +36,6 @@
 /* Console device */
 typedef struct
 {
-    bool  is_async;
     sem_t data_sem;
 } OS_impl_console_internal_record_t;
 

src/os/rtems/src/os-impl-console.c

@@ -67,7 +67,6 @@
 /* Console device */
 typedef struct
 {
-    bool     is_async;
     rtems_id data_sem;
     int      out_fd;
 } OS_impl_console_internal_record_t;
@@ -93,16 +92,9 @@ void OS_ConsoleWakeup_Impl(const OS_object_token_t *token)
 
     local = OS_OBJECT_TABLE_GET(OS_impl_console_table, *token);
 
-    if (local->is_async)
-    {
-        /* post the sem for the utility task to run */
-        rtems_semaphore_release(local->data_sem);
-    }
-    else
-    {
-        /* output directly */
-        OS_ConsoleOutput_Impl(token);
-    }
+    /* post the sem for the utility task to run */
+    rtems_semaphore_release(local->data_sem);
+
 } /* end OS_ConsoleWakeup_Impl */
 
 /*----------------------------------------------------------------
@@ -143,20 +135,21 @@ static void OS_ConsoleTask_Entry(rtems_task_argument arg)
 int32 OS_ConsoleCreate_Impl(const OS_object_token_t *token)
 {
     OS_impl_console_internal_record_t *local;
+    OS_console_internal_record_t *     console;
     int32                              return_code;
     rtems_name                         r_name;
     rtems_id                           r_task_id;
     rtems_status_code                  status;
 
-    local = OS_OBJECT_TABLE_GET(OS_impl_console_table, *token);
+    local   = OS_OBJECT_TABLE_GET(OS_impl_console_table, *token);
+    console = OS_OBJECT_TABLE_GET(OS_console_table, *token);
 
     if (OS_ObjectIndexFromToken(token) == 0)
     {
-        return_code     = OS_SUCCESS;
-        local->is_async = OS_CONSOLE_ASYNC;
-        local->out_fd   = OSAL_CONSOLE_FILENO;
+        return_code   = OS_SUCCESS;
+        local->out_fd = OSAL_CONSOLE_FILENO;
 
-        if (local->is_async)
+        if (console->IsAsync)
         {
             OS_DEBUG("%s(): Starting Async Console Handler\n", __func__);
             /*

src/os/shared/inc/os-shared-printf.h

@@ -32,6 +32,31 @@
 #include "os-shared-console.h"
 #include "os-shared-globaldefs.h"
 
+/*
+ * Variables related to the console buffer.
+ * This is a simple ring buffer that decouples
+ * the OS_printf() call from actual console output.
+ *
+ * The implementation layer may optionally spawn a
+ * "utility task" or equivalent to forward data, or
+ * it may process data immediately.
+ */
+
+typedef struct
+{
+    char device_name[OS_MAX_API_NAME];
+
+    char *          BufBase;        /**< Start of the buffer memory */
+    size_t          BufSize;        /**< Total size of the buffer */
+    volatile size_t ReadPos;        /**< Offset of next byte to read */
+    volatile size_t WritePos;       /**< Offset of next byte to write */
+    uint32          OverflowEvents; /**< Number of lines dropped due to overflow */
+    bool            IsAsync;
+
+} OS_console_internal_record_t;
+
+extern OS_console_internal_record_t OS_console_table[OS_MAX_CONSOLES];
+
 /****************************************************************************************
                  CONSOLE / DEBUG API LOW-LEVEL IMPLEMENTATION FUNCTIONS
  ****************************************************************************************/
@@ -48,4 +73,17 @@
  ------------------------------------------------------------------*/
 void OS_ConsoleOutput_Impl(const OS_object_token_t *token);
 
+/*----------------------------------------------------------------
+   Function: OS_ConsoleWakeup_Impl
+
+    Purpose: Console output data notification
+
+   This is a notification API that is invoked whenever there
+   is new data available in the console output buffer.
+
+   It is only used of the console is configured for async operation,
+   and it should wakeup the actual console servicing thread.
+ ------------------------------------------------------------------*/
+void OS_ConsoleWakeup_Impl(const OS_object_token_t *token);
+
 #endif /* OS_SHARED_PRINTF_H */

src/os/shared/src/osapi-printf.c

@@ -56,6 +56,16 @@
 #include "os-shared-idmap.h"
 #include "os-shared-printf.h"
 
+/*
+ * The choice of whether to run a separate utility task
+ * comes from osal compile-time config
+ */
+#ifdef OSAL_CONFIG_CONSOLE_ASYNC
+#define OS_CONSOLE_IS_ASYNC true
+#else
+#define OS_CONSOLE_IS_ASYNC false
+#endif
+
 /* reserve buffer memory for the printf console device */
 static char OS_printf_buffer_mem[(sizeof(OS_PRINTF_CONSOLE_NAME) + OS_BUFFER_SIZE) * OS_BUFFER_MSG_DEPTH];
 
@@ -99,6 +109,7 @@ int32 OS_ConsoleAPI_Init(void)
          */
         console->BufBase = OS_printf_buffer_mem;
         console->BufSize = sizeof(OS_printf_buffer_mem);
+        console->IsAsync = OS_CONSOLE_IS_ASYNC;
 
         return_code = OS_ConsoleCreate_Impl(&token);
 
@@ -234,7 +245,16 @@ int32 OS_ConsoleWrite(osal_id_t console_id, const char *Str)
          * This is done while still locked, so it can support
          * either a synchronous or asynchronous implementation.
          */
-        OS_ConsoleWakeup_Impl(&token);
+        if (console->IsAsync)
+        {
+            /* post the sem for the utility task to run */
+            OS_ConsoleWakeup_Impl(&token);
+        }
+        else
+        {
+            /* output directly */
+            OS_ConsoleOutput_Impl(&token);
+        }
 
         OS_ObjectIdRelease(&token);
     }

src/os/vxworks/inc/os-impl-console.h

@@ -37,7 +37,6 @@
 typedef struct
 {
     VX_COUNTING_SEMAPHORE(cmem);
-    bool    is_async;
     SEM_ID  datasem;
     TASK_ID taskid;
 } OS_impl_console_internal_record_t;

src/os/vxworks/src/os-impl-console.c

@@ -74,19 +74,12 @@ void OS_ConsoleWakeup_Impl(const OS_object_token_t *token)
 
     local = OS_OBJECT_TABLE_GET(OS_impl_console_table, *token);
 
-    if (local->is_async)
+    /* post the sem for the utility task to run */
+    if (semGive(local->datasem) == ERROR)
     {
-        /* post the sem for the utility task to run */
-        if (semGive(local->datasem) == ERROR)
-        {
-            OS_DEBUG("semGive() - vxWorks errno %d\n", errno);
-        }
-    }
-    else
-    {
-        /* output directly */
-        OS_ConsoleOutput_Impl(token);
+        OS_DEBUG("semGive() - vxWorks errno %d\n", errno);
     }
+
 } /* end OS_ConsoleWakeup_Impl */
 
 /*----------------------------------------------------------------
@@ -142,10 +135,9 @@ int32 OS_ConsoleCreate_Impl(const OS_object_token_t *token)
 
     if (OS_ObjectIndexFromToken(token) == 0)
     {
-        return_code     = OS_SUCCESS;
-        local->is_async = OS_CONSOLE_ASYNC;
+        return_code = OS_SUCCESS;
 
-        if (local->is_async)
+        if (console->IsAsync)
         {
             OS_DEBUG("%s(): Starting Async Console Handler\n", __func__);
 

src/unit-test-coverage/shared/src/coveragetest-printf.c

@@ -64,7 +64,6 @@ void Test_OS_printf(void)
      * void OS_printf_disable(void);
      * void OS_printf_enable(void);
      */
-    uint32 CallCount = 0;
 
     /* catch case where OS_printf called before init */
     OS_SharedGlobalVars.PrintfConsoleId = OS_OBJECT_ID_UNDEFINED;
@@ -80,17 +79,29 @@ void Test_OS_printf(void)
     UtAssert_True(OS_console_table[0].WritePos == 0, "WritePos (%lu) >= 0",
                   (unsigned long)OS_console_table[0].WritePos);
 
-    /* normal case */
+    /* normal case - sync mode */
+    OS_console_table[0].IsAsync = false;
     OS_printf_enable();
-    OS_printf("UnitTest3");
-    CallCount = UT_GetStubCount(UT_KEY(OS_ConsoleWakeup_Impl));
-    UtAssert_True(CallCount == 1, "OS_ConsoleWakeup_Impl() call count (%lu) == 1", (unsigned long)CallCount);
-    UtAssert_True(OS_console_table[0].WritePos >= 9, "WritePos (%lu) >= 9",
+    OS_printf("UnitTest3s");
+    UtAssert_STUB_COUNT(OS_ConsoleWakeup_Impl, 0);
+    UtAssert_STUB_COUNT(OS_ConsoleOutput_Impl, 1);
+    UtAssert_True(OS_console_table[0].WritePos >= 10, "WritePos (%lu) >= 10",
+                  (unsigned long)OS_console_table[0].WritePos);
+
+    /* normal case - async mode */
+    OS_console_table[0].IsAsync  = true;
+    OS_console_table[0].WritePos = 0;
+    OS_printf("UnitTest3a");
+    UtAssert_STUB_COUNT(OS_ConsoleWakeup_Impl, 1);
+    UtAssert_STUB_COUNT(OS_ConsoleOutput_Impl, 1);
+    UtAssert_True(OS_console_table[0].WritePos >= 10, "WritePos (%lu) >= 10",
                   (unsigned long)OS_console_table[0].WritePos);
 
     /* print a long string that does not fit in the 16-char buffer */
     OS_printf_enable();
     OS_printf("UnitTest4BufferLengthExceeded");
+    UtAssert_True(OS_console_table[0].OverflowEvents == 1, "OverflowEvents (%lu) == 1",
+                  (unsigned long)OS_console_table[0].OverflowEvents);
 
     /* test writing with a non-empty console name */
     strncpy(OS_console_table[0].device_name, "ut", sizeof(OS_console_table[0].device_name) - 1);

src/unit-test-coverage/vxworks/adaptors/inc/ut-adaptor-console.h

@@ -39,9 +39,4 @@ extern size_t const UT_Ref_OS_impl_console_table_SIZE;
  */
 extern void UT_ConsoleTest_TaskEntry(int arg);
 
-/**
- * Force the "is_async" field to a given state for coverage testing
- */
-extern void UT_ConsoleTest_SetConsoleAsync(osal_index_t local_id, bool is_async);
-
 #endif /* UT_ADAPTOR_CONSOLE_H */

src/unit-test-coverage/vxworks/adaptors/src/ut-adaptor-console.c

@@ -39,8 +39,3 @@ void UT_ConsoleTest_TaskEntry(int arg)
 {
     OS_VxWorks_ConsoleTask_Entry(arg);
 }
-
-void UT_ConsoleTest_SetConsoleAsync(osal_index_t local_id, bool is_async)
-{
-    OS_impl_console_table[local_id].is_async = is_async;
-}

src/unit-test-coverage/vxworks/src/coveragetest-console.c

@@ -43,18 +43,13 @@ void Test_OS_ConsoleWakeup_Impl(void)
      */
     OS_object_token_t token = UT_TOKEN_0;
 
-    /* no return code - check for coverage */
-    UT_ConsoleTest_SetConsoleAsync(0, true);
+    /* this just gives the sem, only called in async mode */
     OS_ConsoleWakeup_Impl(&token);
     UtAssert_True(UT_GetStubCount(UT_KEY(OCS_semGive)) == 1, "semGive() called in async mode");
 
+    /* Failure only causes a debug message to be generated, no error handling here */
     UT_SetDefaultReturnValue(UT_KEY(OCS_semGive), -1);
     OS_ConsoleWakeup_Impl(&token);
-
-    UT_ConsoleTest_SetConsoleAsync(0, false);
-    OS_console_table[0].WritePos = 1;
-    OS_ConsoleWakeup_Impl(&token);
-    UtAssert_True(UT_GetStubCount(UT_KEY(OS_ConsoleOutput_Impl)) == 1, "OS_ConsoleOutput_Impl() called in sync mode");
 }
 
 void Test_OS_ConsoleCreate_Impl(void)
@@ -63,8 +58,15 @@ void Test_OS_ConsoleCreate_Impl(void)
 
     memset(&token, 0, sizeof(token));
 
+    /* Verify coverage when configured for sync mode */
+    OS_console_table[0].IsAsync = false;
+    OSAPI_TEST_FUNCTION_RC(OS_ConsoleCreate_Impl(&token), OS_SUCCESS);
+    UtAssert_STUB_COUNT(OCS_taskSpawn, 0); /* Task _was not_ spawned */
+
+    /* Verify coverage when configured for async mode */
+    OS_console_table[0].IsAsync = true;
     OSAPI_TEST_FUNCTION_RC(OS_ConsoleCreate_Impl(&token), OS_SUCCESS);
-    UtAssert_True(UT_GetStubCount(UT_KEY(OCS_taskSpawn)) == 1, "taskSpawn() called");
+    UtAssert_STUB_COUNT(OCS_taskSpawn, 1); /* Task _was_ spawned */
 
     UT_SetDefaultReturnValue(UT_KEY(OCS_semCInitialize), OCS_ERROR);
     OSAPI_TEST_FUNCTION_RC(OS_ConsoleCreate_Impl(&token), OS_SEM_FAILURE);