From a2688377f67cfb7c1cbc5db9bda3c4aeca0872b0 Mon Sep 17 00:00:00 2001 From: Joseph Hickey Date: Wed, 8 Apr 2020 17:12:30 -0400 Subject: [PATCH] Fix #456, Perf log threading and concurrency issues Replaces the `OS_IntLock` with a standard OSAL mutex for protecting the shared/global perflog data structure. This may introduce unexpected task switches when contention occurs, but it ensures proper exclusion with respect to the data structures. Removes the temporary child worker task that was spawned for writing the log data to a file, and replace with a more generic CFE ES background task. The background task is started at boot and pends on a semaphore until there is work to do. The background performance log dump is implemented as a state machine which is called repeatedly over time from the background job task. This performs a limited amount of work on each invocation, and resumes where it left from the previous invocation. --- fsw/cfe-core/src/es/cfe_es_backgroundtask.c | 250 +++++++++ fsw/cfe-core/src/es/cfe_es_global.h | 40 +- fsw/cfe-core/src/es/cfe_es_perf.c | 531 ++++++++++++------ fsw/cfe-core/src/es/cfe_es_perf.h | 82 ++- fsw/cfe-core/src/es/cfe_es_start.c | 26 + fsw/cfe-core/src/es/cfe_es_task.c | 161 +++--- fsw/cfe-core/src/es/cfe_es_task.h | 18 +- fsw/cfe-core/src/inc/cfe_es_events.h | 17 - .../src/inc/private/cfe_es_perfdata_typedef.h | 9 +- fsw/cfe-core/unit-test/es_UT.c | 248 +++++--- fsw/cfe-core/unit-test/es_UT.h | 17 + 11 files changed, 1042 insertions(+), 357 deletions(-) create mode 100644 fsw/cfe-core/src/es/cfe_es_backgroundtask.c diff --git a/fsw/cfe-core/src/es/cfe_es_backgroundtask.c b/fsw/cfe-core/src/es/cfe_es_backgroundtask.c new file mode 100644 index 000000000..174c2952c --- /dev/null +++ b/fsw/cfe-core/src/es/cfe_es_backgroundtask.c @@ -0,0 +1,250 @@ +/* +** GSC-18128-1, "Core Flight Executive Version 6.7" +** +** Copyright (c) 2006-2019 United States Government as represented by +** the Administrator of the National Aeronautics and Space Administration. +** All Rights Reserved. +** +** Licensed under the Apache License, Version 2.0 (the "License"); +** you may not use this file except in compliance with the License. +** You may obtain a copy of the License at +** +** http://www.apache.org/licenses/LICENSE-2.0 +** +** Unless required by applicable law or agreed to in writing, software +** distributed under the License is distributed on an "AS IS" BASIS, +** WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +** See the License for the specific language governing permissions and +** limitations under the License. +*/ + +/* +** File: cfe_es_backgroundtask.c +** +** Purpose: This file contains the implementation of the ES "background task" +** +** This task sits idle most of the time, but is woken by the ES application +** for various maintenance duties that may take time to execute, such as +** writing status/log files. +** +*/ + +/* +** Include Section +*/ + +#include + +#include "osapi.h" +#include "private/cfe_private.h" +#include "cfe_es_perf.h" +#include "cfe_es_global.h" +#include "cfe_es_task.h" + +#define CFE_ES_BACKGROUND_SEM_NAME "ES_BackgroundSem" +#define CFE_ES_BACKGROUND_CHILD_NAME "ES_BackgroundTask" +#define CFE_ES_BACKGROUND_CHILD_STACK_PTR NULL +#define CFE_ES_BACKGROUND_CHILD_STACK_SIZE CFE_PLATFORM_ES_PERF_CHILD_STACK_SIZE +#define CFE_ES_BACKGROUND_CHILD_PRIORITY CFE_PLATFORM_ES_PERF_CHILD_PRIORITY +#define CFE_ES_BACKGROUND_CHILD_FLAGS 0 +#define CFE_ES_BACKGROUND_MAX_IDLE_DELAY 30000 /* 30 seconds */ + + +typedef struct +{ + bool (*RunFunc)(uint32 ElapsedTime, void *Arg); + void *JobArg; + uint32 ActivePeriod; /**< max wait/delay time between calls when job is active */ + uint32 IdlePeriod; /**< max wait/delay time between calls when job is idle */ +} CFE_ES_BackgroundJobEntry_t; + +/* + * List of "background jobs" + * + * This is just a list of functions to periodically call from the context of the background task, + * and can be added/extended as needed. + * + * Each Job function returns a boolean, and should return "true" if it is active, or "false" if it is idle. + * + * This uses "cooperative multitasking" -- the function should do some limited work, then return to the + * background task. It will be called again after a delay period to do more work. + */ +const CFE_ES_BackgroundJobEntry_t CFE_ES_BACKGROUND_JOB_TABLE[] = +{ + { /* Performance Log Data Dump to file */ + .RunFunc = CFE_ES_RunPerfLogDump, + .JobArg = &CFE_ES_TaskData.BackgroundPerfDumpState, + .ActivePeriod = CFE_PLATFORM_ES_PERF_CHILD_MS_DELAY, + .IdlePeriod = CFE_PLATFORM_ES_PERF_CHILD_MS_DELAY * 1000 + } +}; + +#define CFE_ES_BACKGROUND_NUM_JOBS (sizeof(CFE_ES_BACKGROUND_JOB_TABLE) / sizeof(CFE_ES_BACKGROUND_JOB_TABLE[0])) + +/* * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * */ +/* Name: CFE_ES_BackgroundTask */ +/* */ +/* Purpose: A helper task for low priority routines that may take time to */ +/* execute, such as writing log files. */ +/* */ +/* Assumptions and Notes: This is started from the ES initialization, and */ +/* pends on a semaphore until a work request comes in. This is intended to */ +/* avoid the need to create a child task "on demand" when work items arrive, */ +/* which is a form of dynamic allocation. */ +/* */ +/* * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * */ +void CFE_ES_BackgroundTask(void) +{ + int32 status; + uint32 JobTotal; + uint32 NumJobsRunning; + uint32 NextDelay; + uint32 ElapsedTime; + OS_time_t CurrTime; + OS_time_t LastTime; + const CFE_ES_BackgroundJobEntry_t *JobPtr; + + status = CFE_ES_RegisterChildTask(); + if (status != CFE_SUCCESS) + { + /* should never occur */ + CFE_ES_WriteToSysLog("CFE_ES: Background Task Failed to register: %08lx\n", (unsigned long)status); + return; + } + + CFE_PSP_GetTime(&LastTime); + + while (true) + { + /* + * compute the elapsed time (difference) between last + * execution and now, in microseconds. + * + * Note this calculation is done as a uint32 which will overflow + * after about 35 minutes, but the max delays ensure that this + * executes at least every few seconds, so that should never happen. + */ + CFE_PSP_GetTime(&CurrTime); + ElapsedTime = 1000000 * (CurrTime.seconds - LastTime.seconds); + ElapsedTime += CurrTime.microsecs; + ElapsedTime -= LastTime.microsecs; + LastTime = CurrTime; + + /* + * convert to milliseconds. + * we do not really need high precision + * for background task timings + */ + ElapsedTime /= 1000; + + NextDelay = CFE_ES_BACKGROUND_MAX_IDLE_DELAY; /* default; will be adjusted based on active jobs */ + JobPtr = CFE_ES_BACKGROUND_JOB_TABLE; + JobTotal = CFE_ES_BACKGROUND_NUM_JOBS; + NumJobsRunning = 0; + + while (JobTotal > 0) + { + /* + * call the background job - + * if it returns "true" that means it is active, + * if it returns "false" that means it is idle + */ + if (JobPtr->RunFunc != NULL && JobPtr->RunFunc(ElapsedTime, JobPtr->JobArg)) + { + ++NumJobsRunning; + + if (JobPtr->ActivePeriod != 0 && NextDelay > JobPtr->ActivePeriod) + { + /* next delay is based on this active job wait time */ + NextDelay = JobPtr->ActivePeriod; + } + } + else if (JobPtr->IdlePeriod != 0 && NextDelay > JobPtr->IdlePeriod) + { + /* next delay is based on this idle job wait time */ + NextDelay = JobPtr->IdlePeriod; + } + --JobTotal; + ++JobPtr; + } + + CFE_ES_Global.BackgroundTask.NumJobsRunning = NumJobsRunning; + + status = OS_BinSemTimedWait(CFE_ES_Global.BackgroundTask.WorkSem, NextDelay); + if (status != OS_SUCCESS && status != OS_SEM_TIMEOUT) + { + /* should never occur */ + CFE_ES_WriteToSysLog("CFE_ES: Failed to take background sem: %08lx\n", (unsigned long)status); + break; + } + + } +} + +/* * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * */ +/* Name: CFE_ES_BackgroundInit */ +/* */ +/* Purpose: Initialize the background task */ +/* */ +/* * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * */ +int32 CFE_ES_BackgroundInit(void) +{ + int32 status; + + status = OS_BinSemCreate(&CFE_ES_Global.BackgroundTask.WorkSem, CFE_ES_BACKGROUND_SEM_NAME, 0, 0); + if (status != OS_SUCCESS) + { + CFE_ES_WriteToSysLog("CFE_ES: Failed to create background sem: %08lx\n", (unsigned long)status); + return status; + } + + /* Spawn a task to write the performance data to a file */ + status = CFE_ES_CreateChildTask(&CFE_ES_Global.BackgroundTask.TaskID, + CFE_ES_BACKGROUND_CHILD_NAME, + CFE_ES_BackgroundTask, + CFE_ES_BACKGROUND_CHILD_STACK_PTR, + CFE_ES_BACKGROUND_CHILD_STACK_SIZE, + CFE_ES_BACKGROUND_CHILD_PRIORITY, + CFE_ES_BACKGROUND_CHILD_FLAGS); + + if (status != OS_SUCCESS) + { + CFE_ES_WriteToSysLog("CFE_ES: Failed to create background task: %08lx\n", (unsigned long)status); + return status; + } + + return CFE_SUCCESS; +} + +/* * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * */ +/* Name: CFE_ES_BackgroundCleanup */ +/* */ +/* Purpose: Exit/Stop the background task */ +/* */ +/* * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * */ +void CFE_ES_BackgroundCleanup(void) +{ + CFE_ES_DeleteChildTask(CFE_ES_Global.BackgroundTask.TaskID); + OS_BinSemDelete(CFE_ES_Global.BackgroundTask.WorkSem); + + CFE_ES_Global.BackgroundTask.TaskID = 0; + CFE_ES_Global.BackgroundTask.WorkSem = 0; +} + +/* * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * */ +/* Name: CFE_ES_BackgroundWakeup */ +/* */ +/* Purpose: Wake up the background task */ +/* Notifies the background task to perform an extra poll for new work */ +/* */ +/* * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * */ +void CFE_ES_BackgroundWakeup(void) +{ + /* wake up the background task by giving the sem. + * This is "informational" and not strictly required, + * but it will make the task immediately wake up and check for new + * work if it was idle. */ + OS_BinSemGive(CFE_ES_Global.BackgroundTask.WorkSem); +} + + diff --git a/fsw/cfe-core/src/es/cfe_es_global.h b/fsw/cfe-core/src/es/cfe_es_global.h index 756fce951..16c13c417 100644 --- a/fsw/cfe-core/src/es/cfe_es_global.h +++ b/fsw/cfe-core/src/es/cfe_es_global.h @@ -19,8 +19,8 @@ */ /* -** File: -** cfe_es_global.h +** File: +** cfe_es_global.h ** ** Purpose: ** This file contains the ES global data definitions. @@ -66,13 +66,23 @@ typedef struct { bool RecordUsed; /* Is the record used(1) or available(0) ? */ uint32 Counter; - char CounterName[OS_MAX_API_NAME]; /* Counter Name */ + char CounterName[OS_MAX_API_NAME]; /* Counter Name */ } CFE_ES_GenCounterRecord_t; +/* + * Encapsulates the state of the ES background task + */ +typedef struct +{ + uint32 TaskID; /**< OSAL ID of the background task */ + uint32 WorkSem; /**< Semaphore that is given whenever background work is pending */ + uint32 NumJobsRunning; /**< Current Number of active jobs (updated by background task) */ +} CFE_ES_BackgroundTaskState_t; + /* ** Executive Services Global Memory Data -** This is the regular global data that is not preserved on a +** This is the regular global data that is not preserved on a ** processor reset. */ typedef struct @@ -81,12 +91,17 @@ typedef struct ** Debug Variables */ CFE_ES_DebugVariables_t DebugVars; - + /* ** Shared Data Semaphore */ uint32 SharedDataMutex; - + + /* + ** Performance Data Mutex + */ + uint32 PerfDataMutex; + /* ** Startup Sync */ @@ -94,7 +109,7 @@ typedef struct /* ** ES Task Table - */ + */ uint32 RegisteredTasks; CFE_ES_TaskRecord_t TaskTable[OS_MAX_TASKS]; @@ -104,7 +119,7 @@ typedef struct uint32 RegisteredCoreApps; uint32 RegisteredExternalApps; CFE_ES_AppRecord_t AppTable[CFE_PLATFORM_ES_MAX_APPLICATIONS]; - + /* ** ES Shared Library Table */ @@ -121,12 +136,19 @@ typedef struct */ CFE_ES_CDSVariables_t CDSVars; + /* + * Background task for handling long-running, non real time tasks + * such as maintenance, file writes, and other items. + */ + CFE_ES_BackgroundTaskState_t BackgroundTask; + + } CFE_ES_Global_t; /* ** The Executive Services Global Data declaration */ -extern CFE_ES_Global_t CFE_ES_Global; +extern CFE_ES_Global_t CFE_ES_Global; /* ** The Executive Services Nonvolatile Data declaration diff --git a/fsw/cfe-core/src/es/cfe_es_perf.c b/fsw/cfe-core/src/es/cfe_es_perf.c index d42a923e7..308514d20 100644 --- a/fsw/cfe-core/src/es/cfe_es_perf.c +++ b/fsw/cfe-core/src/es/cfe_es_perf.c @@ -47,7 +47,7 @@ ** Pointer to performance log in the reset area */ CFE_ES_PerfData_t *Perf; -CFE_ES_PerfLogDump_t CFE_ES_PerfLogDumpStatus; + /* * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * */ /* Name: CFE_ES_SetupPerfVariables */ @@ -112,10 +112,45 @@ void CFE_ES_SetupPerfVariables(uint32 ResetType) } } +} - CFE_ES_PerfLogDumpStatus.DataToWrite = 0; - CFE_ES_PerfLogDumpStatus.ChildID = 0; - CFE_ES_PerfLogDumpStatus.DataFileName[0] = '\0'; +/* * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * */ +/* */ +/* CFE_ES_GetPerfLogDumpRemaining() -- */ +/* Estimate the number of perf log entries left to write */ +/* This is used for telemetry/progress reporting for the perf log dump request */ +/* */ +/* * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * */ +uint32 CFE_ES_GetPerfLogDumpRemaining(void) +{ + CFE_ES_PerfDumpGlobal_t *PerfDumpState = &CFE_ES_TaskData.BackgroundPerfDumpState; + CFE_ES_PerfDumpState_t CurrentState = PerfDumpState->CurrentState; + uint32 Result; + + /* note this reads the data "live" without exclusion and as such it + * may change even between checking the state and checking the value. + * This shouldn't be a big deal, as the result should still be meaningful + * for a progress report, and the actual 32-bit counters should be atomic */ + if (CurrentState > CFE_ES_PerfDumpState_IDLE && + CurrentState < CFE_ES_PerfDumpState_WRITE_PERF_ENTRIES) + { + /* dump is requested but not yet to entry writing state, + * report the entire data count from perf log */ + Result = Perf->MetaData.DataCount; + } + else if (CurrentState == CFE_ES_PerfDumpState_WRITE_PERF_ENTRIES) + { + /* dump is in active writing state, + * report the block counter (number remaining) */ + Result = PerfDumpState->StateCounter; + } + else + { + /* no dump active or dump is complete, report 0 */ + Result = 0; + } + + return Result; } /* * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * */ @@ -126,9 +161,11 @@ void CFE_ES_SetupPerfVariables(uint32 ResetType) int32 CFE_ES_StartPerfDataCmd(const CFE_ES_StartPerfData_t *data) { const CFE_ES_StartPerfCmd_Payload_t *CmdPtr = &data->Payload; + CFE_ES_PerfDumpGlobal_t *PerfDumpState = &CFE_ES_TaskData.BackgroundPerfDumpState; /* Ensure there is no file write in progress before proceeding */ - if(CFE_ES_PerfLogDumpStatus.DataToWrite == 0) + if(PerfDumpState->CurrentState == CFE_ES_PerfDumpState_IDLE && + PerfDumpState->PendingState == CFE_ES_PerfDumpState_IDLE) { /* Make sure Trigger Mode is valid */ /* cppcheck-suppress unsignedPositive */ @@ -137,6 +174,9 @@ int32 CFE_ES_StartPerfDataCmd(const CFE_ES_StartPerfData_t *data) CFE_ES_TaskData.CommandCounter++; + /* Taking lock here as this might be changing states from one active mode to another. + * In that case, need to make sure that the log is not written to while resetting the counters. */ + OS_MutSemTake(CFE_ES_Global.PerfDataMutex); Perf->MetaData.Mode = CmdPtr->TriggerMode; Perf->MetaData.TriggerCount = 0; Perf->MetaData.DataStart = 0; @@ -144,6 +184,7 @@ int32 CFE_ES_StartPerfDataCmd(const CFE_ES_StartPerfData_t *data) Perf->MetaData.DataCount = 0; Perf->MetaData.InvalidMarkerReported = false; Perf->MetaData.State = CFE_ES_PERF_WAITING_FOR_TRIGGER; /* this must be done last */ + OS_MutSemGive(CFE_ES_Global.PerfDataMutex); CFE_EVS_SendEvent(CFE_ES_PERF_STARTCMD_EID, CFE_EVS_EventType_DEBUG, "Start collecting performance data cmd received, trigger mode = %d", @@ -176,59 +217,30 @@ int32 CFE_ES_StartPerfDataCmd(const CFE_ES_StartPerfData_t *data) int32 CFE_ES_StopPerfDataCmd(const CFE_ES_StopPerfData_t *data) { const CFE_ES_StopPerfCmd_Payload_t *CmdPtr = &data->Payload; - int32 Stat; + CFE_ES_PerfDumpGlobal_t *PerfDumpState = &CFE_ES_TaskData.BackgroundPerfDumpState; /* Ensure there is no file write in progress before proceeding */ - if(CFE_ES_PerfLogDumpStatus.DataToWrite == 0) + /* note - also need to check the PendingState here, in case this command + * was sent twice in succession and the background task has not awakened yet */ + if(PerfDumpState->CurrentState == CFE_ES_PerfDumpState_IDLE && + PerfDumpState->PendingState == CFE_ES_PerfDumpState_IDLE) { Perf->MetaData.State = CFE_ES_PERF_IDLE; /* Copy out the string, using default if unspecified */ - CFE_SB_MessageStringGet(CFE_ES_PerfLogDumpStatus.DataFileName, CmdPtr->DataFileName, + CFE_SB_MessageStringGet(PerfDumpState->DataFileName, CmdPtr->DataFileName, CFE_PLATFORM_ES_DEFAULT_PERF_DUMP_FILENAME, OS_MAX_PATH_LEN, sizeof(CmdPtr->DataFileName)); - /* Create the file to dump to */ - CFE_ES_PerfLogDumpStatus.DataFileDescriptor = OS_creat(&CFE_ES_PerfLogDumpStatus.DataFileName[0], OS_WRITE_ONLY); + PerfDumpState->PendingState = CFE_ES_PerfDumpState_INIT; + CFE_ES_BackgroundWakeup(); + CFE_ES_TaskData.CommandCounter++; - if(CFE_ES_PerfLogDumpStatus.DataFileDescriptor < 0) - { - CFE_ES_TaskData.CommandErrorCounter++; - CFE_EVS_SendEvent(CFE_ES_PERF_LOG_ERR_EID,CFE_EVS_EventType_ERROR, - "Error creating file %s, RC = 0x%08X", - &CFE_ES_PerfLogDumpStatus.DataFileName[0], (unsigned int)CFE_ES_PerfLogDumpStatus.DataFileDescriptor); - } - else - { - - /* Spawn a task to write the performance data to a file */ - Stat = CFE_ES_CreateChildTask(&CFE_ES_PerfLogDumpStatus.ChildID, - CFE_ES_PERF_CHILD_NAME, - CFE_ES_PerfLogDump, - CFE_ES_PERF_CHILD_STACK_PTR, - CFE_PLATFORM_ES_PERF_CHILD_STACK_SIZE, - CFE_PLATFORM_ES_PERF_CHILD_PRIORITY, - CFE_ES_PERF_CHILD_FLAGS); - - if(Stat == CFE_SUCCESS) - { - /* Note: the file gets closed in the child task */ - CFE_ES_TaskData.CommandCounter++; - CFE_EVS_SendEvent(CFE_ES_PERF_STOPCMD_EID,CFE_EVS_EventType_DEBUG, - "Perf Stop Cmd Rcvd,%s will write %d entries.%dmS dly every %d entries", - CFE_ES_PERF_CHILD_NAME,(int)Perf->MetaData.DataCount, - (int)CFE_PLATFORM_ES_PERF_CHILD_MS_DELAY,(int)CFE_PLATFORM_ES_PERF_ENTRIES_BTWN_DLYS); - } - else - { - /* close the fd */ - OS_close( CFE_ES_PerfLogDumpStatus.DataFileDescriptor); - CFE_ES_TaskData.CommandErrorCounter++; - CFE_EVS_SendEvent(CFE_ES_PERF_STOPCMD_ERR1_EID, CFE_EVS_EventType_ERROR, - "Stop performance data cmd,Error creating child task RC=0x%08X",(unsigned int)Stat); - }/* end if */ - - }/* end if fd < 0 */ + CFE_EVS_SendEvent(CFE_ES_PERF_STOPCMD_EID,CFE_EVS_EventType_DEBUG, + "Perf Stop Cmd Rcvd, will write %d entries.%dmS dly every %d entries", + (int)Perf->MetaData.DataCount, + (int)CFE_PLATFORM_ES_PERF_CHILD_MS_DELAY, + (int)CFE_PLATFORM_ES_PERF_ENTRIES_BTWN_DLYS); }/* if data to write == 0 */ else @@ -244,88 +256,233 @@ int32 CFE_ES_StopPerfDataCmd(const CFE_ES_StopPerfData_t *data) /* * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * */ -/* Function: CFE_ES_PerfLogDump() */ +/* Function: CFE_ES_RunPerfLogDump() */ /* */ /* Purpose: */ /* Write performance data to a file */ +/* This is implemented as a state machine that is invoked in the background */ +/* Each iteration should perform a limited amount of work, which will resume */ +/* on the next iteration. State is kept in a global structure. */ /* */ /* Arguments: */ /* None */ /* */ /* * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * */ -void CFE_ES_PerfLogDump(void){ - +bool CFE_ES_RunPerfLogDump(uint32 ElapsedTime, void *Arg) +{ + CFE_ES_PerfDumpGlobal_t *State = (CFE_ES_PerfDumpGlobal_t *)Arg; int32 WriteStat; - uint32 i; - uint32 FileSize; CFE_FS_Header_t FileHdr; + uint32 BlockSize; - CFE_ES_RegisterChildTask(); - - - /* Zero cFE header, then fill in fields */ - CFE_FS_InitHeader(&FileHdr, CFE_ES_PERF_LOG_DESC, CFE_FS_SubType_ES_PERFDATA); + /* + * each time this background job is re-entered after a time delay, + * accumulate a work credit amount based on the elapsed time. + * + * This implements work-throttling as a form of cooperative + * CPU sharing with other low priority background jobs. + */ + State->WorkCredit += + (ElapsedTime * CFE_PLATFORM_ES_PERF_ENTRIES_BTWN_DLYS) / CFE_PLATFORM_ES_PERF_CHILD_MS_DELAY; - /* write the cFE header to the file */ - WriteStat = CFE_FS_WriteHeader( CFE_ES_PerfLogDumpStatus.DataFileDescriptor, &FileHdr); - if(WriteStat != sizeof(CFE_FS_Header_t)) + /* + * do not allow credit to accumulate indefinitely - + * after a long idle time this would defeat the purpose. + */ + if (State->WorkCredit > CFE_PLATFORM_ES_PERF_ENTRIES_BTWN_DLYS) { - CFE_ES_FileWriteByteCntErr(&CFE_ES_PerfLogDumpStatus.DataFileName[0], - sizeof(CFE_FS_Header_t),WriteStat); - - OS_close(CFE_ES_PerfLogDumpStatus.DataFileDescriptor); - CFE_ES_ExitChildTask(); - /* normally ExitChildTask() does not return, but it DOES under UT */ - return; - }/* end if */ - FileSize = WriteStat; + State->WorkCredit = CFE_PLATFORM_ES_PERF_ENTRIES_BTWN_DLYS; + } - /* write the performance metadata to the file */ - WriteStat = OS_write(CFE_ES_PerfLogDumpStatus.DataFileDescriptor,&Perf->MetaData,sizeof(CFE_ES_PerfMetaData_t)); - if(WriteStat != sizeof(CFE_ES_PerfMetaData_t)) + while (State->WorkCredit > 0) { - CFE_ES_FileWriteByteCntErr(&CFE_ES_PerfLogDumpStatus.DataFileName[0], - sizeof(CFE_ES_PerfMetaData_t),WriteStat); - OS_close(CFE_ES_PerfLogDumpStatus.DataFileDescriptor); - CFE_ES_ExitChildTask(); - /* normally ExitChildTask() does not return, but it DOES under UT */ - return; - }/* end if */ - FileSize += WriteStat; - - CFE_ES_PerfLogDumpStatus.DataToWrite = Perf->MetaData.DataCount; - - /* write the collected data to the file */ - for(i=0; i < Perf->MetaData.DataCount; i++){ - WriteStat = OS_write (CFE_ES_PerfLogDumpStatus.DataFileDescriptor, &Perf->DataBuffer[i], sizeof(CFE_ES_PerfDataEntry_t)); - if(WriteStat != sizeof(CFE_ES_PerfDataEntry_t)) - { - CFE_ES_FileWriteByteCntErr(&CFE_ES_PerfLogDumpStatus.DataFileName[0], - sizeof(CFE_ES_PerfDataEntry_t),WriteStat); - OS_close(CFE_ES_PerfLogDumpStatus.DataFileDescriptor); - /* Reset the DataToWrite variable, so a new file can be written */ - CFE_ES_PerfLogDumpStatus.DataToWrite = 0; - CFE_ES_ExitChildTask(); - /* normally ExitChildTask() does not return, but it DOES under UT */ - return; - }/* end if */ - FileSize += WriteStat; - CFE_ES_PerfLogDumpStatus.DataToWrite--; - if((i % CFE_PLATFORM_ES_PERF_ENTRIES_BTWN_DLYS) == 0){ - OS_TaskDelay(CFE_PLATFORM_ES_PERF_CHILD_MS_DELAY); - }/* end if */ + --State->WorkCredit; + + if (State->PendingState != + State->CurrentState) + { + /* + * Handle state change/entry logic. + * Zero the block counter register (may be changed later). + */ + State->StateCounter = 0; + + switch(State->PendingState) + { + case CFE_ES_PerfDumpState_OPEN_FILE: + /* Create the file to dump to */ + State->FileDesc = OS_creat(State->DataFileName, OS_WRITE_ONLY); + State->FileSize = 0; + break; + + case CFE_ES_PerfDumpState_DELAY: + /* + * Add a state entry delay before locking the "Perf" structure to + * ensure that any foreground task that may have been writing to this + * structure has completed its access. + * + * Note that the state should already have been set to IDLE, so + * no new writes will start, this is just to yield the CPU such that + * any already-started writes may finish. + * + * This can be done by simply zeroing out the current credit, + * which will cause this loop to exit for now and resume after + * some time delay (does not really matter how much time). + */ + State->WorkCredit = 0; + break; + + case CFE_ES_PerfDumpState_LOCK_DATA: + OS_MutSemTake(CFE_ES_Global.PerfDataMutex); + break; + + case CFE_ES_PerfDumpState_WRITE_FS_HDR: + case CFE_ES_PerfDumpState_WRITE_PERF_METADATA: + State->StateCounter = 1; + break; + + case CFE_ES_PerfDumpState_WRITE_PERF_ENTRIES: + State->DataPos = Perf->MetaData.DataStart; + State->StateCounter = Perf->MetaData.DataCount; + break; + + case CFE_ES_PerfDumpState_UNLOCK_DATA: + OS_MutSemGive(CFE_ES_Global.PerfDataMutex); + break; + + case CFE_ES_PerfDumpState_CLOSE_FILE: + /* close the fd */ + if (State->FileDesc != 0) + { + OS_close(State->FileDesc); + State->FileDesc = 0; + } + break; + + default: + break; + } - }/* end for */ + State->CurrentState = State->PendingState; + } - OS_close(CFE_ES_PerfLogDumpStatus.DataFileDescriptor); + if (State->CurrentState == CFE_ES_PerfDumpState_IDLE) + { + break; + } - CFE_EVS_SendEvent(CFE_ES_PERF_DATAWRITTEN_EID,CFE_EVS_EventType_DEBUG, - "%s written:Size=%d,EntryCount=%d", - &CFE_ES_PerfLogDumpStatus.DataFileName[0],(int)FileSize, - (int)Perf->MetaData.DataCount); + if (State->StateCounter == 0) + { + /* + * State is finished, do any final error checking and logging + * + * Default transition is to the next state by numeric value. + * This prevent endless looping in the same state. + * + * The switch statement can override this transition, however, + * based on any relevant error checks. + */ + State->PendingState = 1 + State->CurrentState; + if (State->PendingState >= CFE_ES_PerfDumpState_MAX) + { + State->PendingState = CFE_ES_PerfDumpState_IDLE; + } + switch(State->CurrentState) + { + case CFE_ES_PerfDumpState_OPEN_FILE: + if(State->FileDesc < 0) + { + CFE_EVS_SendEvent(CFE_ES_PERF_LOG_ERR_EID,CFE_EVS_EventType_ERROR, + "Error creating file %s, RC = 0x%08X", + State->DataFileName, (unsigned int)State->FileDesc); + + State->PendingState = CFE_ES_PerfDumpState_IDLE; + } /* end if */ + break; + + case CFE_ES_PerfDumpState_WRITE_PERF_ENTRIES: + CFE_EVS_SendEvent(CFE_ES_PERF_DATAWRITTEN_EID,CFE_EVS_EventType_DEBUG, + "%s written:Size=%lu,EntryCount=%lu", + State->DataFileName, + (unsigned long)State->FileSize, + (unsigned long)Perf->MetaData.DataCount); + break; + + default: + break; + } + } + else + { + /* + * State is in progress, perform work item(s) as required + */ + WriteStat = 0; + BlockSize = 0; + switch(State->CurrentState) + { + case CFE_ES_PerfDumpState_WRITE_FS_HDR: + /* Zero cFE header, then fill in fields */ + CFE_FS_InitHeader(&FileHdr, CFE_ES_PERF_LOG_DESC, CFE_FS_SubType_ES_PERFDATA); + /* predicted total length of final output */ + FileHdr.Length = sizeof(CFE_ES_PerfMetaData_t) + (Perf->MetaData.DataCount * sizeof(CFE_ES_PerfDataEntry_t)); + /* write the cFE header to the file */ + WriteStat = CFE_FS_WriteHeader(State->FileDesc, + &FileHdr); + BlockSize = sizeof(CFE_FS_Header_t); + break; + + case CFE_ES_PerfDumpState_WRITE_PERF_METADATA: + /* write the performance metadata to the file */ + BlockSize = sizeof(CFE_ES_PerfMetaData_t); + WriteStat = OS_write(State->FileDesc, + &Perf->MetaData, BlockSize); + break; + + case CFE_ES_PerfDumpState_WRITE_PERF_ENTRIES: + BlockSize = sizeof(CFE_ES_PerfDataEntry_t); + WriteStat = OS_write (State->FileDesc, + &Perf->DataBuffer[State->DataPos], + BlockSize); + + ++State->DataPos; + if (State->DataPos >= CFE_PLATFORM_ES_PERF_DATA_BUFFER_SIZE) + { + State->DataPos = 0; + } + break; - CFE_ES_ExitChildTask(); + default: + break; + } + if (BlockSize != 0) + { + if (WriteStat != BlockSize) + { + CFE_ES_FileWriteByteCntErr(State->DataFileName, BlockSize, WriteStat); + + /* skip to cleanup */ + if (State->CurrentState < CFE_ES_PerfDumpState_CLEANUP) + { + State->PendingState = CFE_ES_PerfDumpState_CLEANUP; + } + } + else + { + State->FileSize += BlockSize; + } + } + + --State->StateCounter; + } + + } + + /* + * Return "true" if activity is ongoing, or "false" if not active + */ + return (State->CurrentState != CFE_ES_PerfDumpState_IDLE); }/* end CFE_ES_PerfLogDump */ /* * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * */ @@ -414,83 +571,123 @@ int32 CFE_ES_SetPerfTriggerMaskCmd(const CFE_ES_SetPerfTriggerMask_t *data) /* * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * */ void CFE_ES_PerfLogAdd(uint32 Marker, uint32 EntryExit) { - int32 IntFlags; - - if (Perf->MetaData.State != CFE_ES_PERF_IDLE) { + CFE_ES_PerfDataEntry_t EntryData; + uint32 DataEnd; - /* if marker is out of range... */ - if(Marker >= CFE_MISSION_ES_PERF_MAX_IDS){ + /* + * If the global state is idle, exit immediately without locking or doing anything + */ + if (Perf->MetaData.State == CFE_ES_PERF_IDLE) + { + return; + } - /* if marker has not been reported previously ... */ - if(Perf->MetaData.InvalidMarkerReported == false){ - CFE_ES_WriteToSysLog("ES PERF:Invalid performance marker %d,max is %d\n", - (unsigned int)Marker,(CFE_MISSION_ES_PERF_MAX_IDS - 1)); + /* if marker is out of range... */ + if (Marker >= CFE_MISSION_ES_PERF_MAX_IDS) + { + /* if marker has not been reported previously ... */ + if (Perf->MetaData.InvalidMarkerReported == false) + { + CFE_ES_WriteToSysLog("ES PERF:Invalid performance marker %d,max is %d\n", (unsigned int)Marker, + (CFE_MISSION_ES_PERF_MAX_IDS - 1)); Perf->MetaData.InvalidMarkerReported = true; - }/* end if */ - - return; + } /* end if */ - }/* end if */ + return; + } /* end if */ + /* + * check if this ID is filtered. + * This is also done outside the lock - + * normally masks should NOT be changed while perf log is active / non-idle, + * so although this is reading a global it should be constant, and this avoids + * locking (and potential task switch) if the data is ultimately not going to + * be written to the log. + */ + if (!CFE_ES_TEST_LONG_MASK(Perf->MetaData.FilterMask, Marker)) + { + return; + } - /* is this id filtered */ - if (CFE_ES_TEST_LONG_MASK(Perf->MetaData.FilterMask, Marker)) { + /* + * prepare the entry data (timestamp) before locking, + * just in case the locking operation incurs a delay + */ + EntryData.Data = (Marker | (EntryExit << CFE_MISSION_ES_PERF_EXIT_BIT)); + CFE_PSP_Get_Timebase(&EntryData.TimerUpper32, &EntryData.TimerLower32); - /* disable interrupts to guarentee exclusive access to the data structures */ - IntFlags = OS_IntLock(); + /* + * Acquire the perflog mutex before writing into the shared area. + * Note this lock is held for long periods while a background dump + * is taking place, but the dump should never be active at the + * same time that a capture/record is taking place. + */ + OS_MutSemTake(CFE_ES_Global.PerfDataMutex); - Perf->DataBuffer[Perf->MetaData.DataEnd].Data = (Marker | (EntryExit << CFE_MISSION_ES_PERF_EXIT_BIT)); - CFE_PSP_Get_Timebase((uint32*)&Perf->DataBuffer[Perf->MetaData.DataEnd].TimerUpper32,(uint32*)&Perf->DataBuffer[Perf->MetaData.DataEnd].TimerLower32); + /* + * Confirm that the global is still non-idle after lock + * (state could become idle while getting lock) + */ + if (Perf->MetaData.State != CFE_ES_PERF_IDLE) + { + /* copy data to next perflog slot */ + DataEnd = Perf->MetaData.DataEnd; + Perf->DataBuffer[DataEnd] = EntryData; - Perf->MetaData.DataEnd++; - if (Perf->MetaData.DataEnd >= CFE_PLATFORM_ES_PERF_DATA_BUFFER_SIZE) { - Perf->MetaData.DataEnd = 0; - } + ++DataEnd; + if (DataEnd >= CFE_PLATFORM_ES_PERF_DATA_BUFFER_SIZE) + { + DataEnd = 0; + } + Perf->MetaData.DataEnd = DataEnd; - /* we have filled up the buffer */ + /* we have filled up the buffer */ + if (Perf->MetaData.DataCount < CFE_PLATFORM_ES_PERF_DATA_BUFFER_SIZE) + { Perf->MetaData.DataCount++; - if (Perf->MetaData.DataCount > CFE_PLATFORM_ES_PERF_DATA_BUFFER_SIZE) { - - Perf->MetaData.DataCount = CFE_PLATFORM_ES_PERF_DATA_BUFFER_SIZE; + } + else + { + /* after the buffer fills up start and end point to the same entry since we + are now overwriting old data */ + Perf->MetaData.DataStart = Perf->MetaData.DataEnd; + } - /* after the buffer fills up start and end point to the same entry since we - are now overwriting old data */ - Perf->MetaData.DataStart = Perf->MetaData.DataEnd; + /* waiting for trigger */ + if (Perf->MetaData.State == CFE_ES_PERF_WAITING_FOR_TRIGGER) + { + if (CFE_ES_TEST_LONG_MASK(Perf->MetaData.TriggerMask, Marker)) + { + Perf->MetaData.State = CFE_ES_PERF_TRIGGERED; } + } - /* waiting for trigger */ - if (Perf->MetaData.State == CFE_ES_PERF_WAITING_FOR_TRIGGER) { - - if (CFE_ES_TEST_LONG_MASK(Perf->MetaData.TriggerMask, Marker)) { - Perf->MetaData.State = CFE_ES_PERF_TRIGGERED; + /* triggered */ + if (Perf->MetaData.State == CFE_ES_PERF_TRIGGERED) + { + Perf->MetaData.TriggerCount++; + if (Perf->MetaData.Mode == CFE_ES_PERF_TRIGGER_START) + { + if (Perf->MetaData.TriggerCount >= CFE_PLATFORM_ES_PERF_DATA_BUFFER_SIZE) + { + Perf->MetaData.State = CFE_ES_PERF_IDLE; } } - /* triggered */ - if (Perf->MetaData.State == CFE_ES_PERF_TRIGGERED) { - - Perf->MetaData.TriggerCount++; - if (Perf->MetaData.Mode == CFE_ES_PERF_TRIGGER_START) { - - if (Perf->MetaData.TriggerCount >= CFE_PLATFORM_ES_PERF_DATA_BUFFER_SIZE) { - Perf->MetaData.State = CFE_ES_PERF_IDLE; - } - } - else if (Perf->MetaData.Mode == CFE_ES_PERF_TRIGGER_CENTER) { - - if (Perf->MetaData.TriggerCount >= CFE_PLATFORM_ES_PERF_DATA_BUFFER_SIZE / 2) { - Perf->MetaData.State = CFE_ES_PERF_IDLE; - } - } - else if (Perf->MetaData.Mode == CFE_ES_PERF_TRIGGER_END) { - + else if (Perf->MetaData.Mode == CFE_ES_PERF_TRIGGER_CENTER) + { + if (Perf->MetaData.TriggerCount >= CFE_PLATFORM_ES_PERF_DATA_BUFFER_SIZE / 2) + { Perf->MetaData.State = CFE_ES_PERF_IDLE; } } - - /* enable interrupts */ - OS_IntUnlock(IntFlags); + else if (Perf->MetaData.Mode == CFE_ES_PERF_TRIGGER_END) + { + Perf->MetaData.State = CFE_ES_PERF_IDLE; + } } } -}/* end CFE_ES_PerfLogAdd */ + OS_MutSemGive(CFE_ES_Global.PerfDataMutex); + +} /* end CFE_ES_PerfLogAdd */ diff --git a/fsw/cfe-core/src/es/cfe_es_perf.h b/fsw/cfe-core/src/es/cfe_es_perf.h index f2c195428..05d05afde 100644 --- a/fsw/cfe-core/src/es/cfe_es_perf.h +++ b/fsw/cfe-core/src/es/cfe_es_perf.h @@ -49,10 +49,6 @@ /* ** Defines */ -#define CFE_ES_PERF_CHILD_NAME "ES_PerfFileWriter" -#define CFE_ES_PERF_CHILD_STACK_PTR 0 -#define CFE_ES_PERF_CHILD_FLAGS 0 - enum CFE_ES_PerfState_t { CFE_ES_PERF_IDLE = 0, @@ -68,14 +64,78 @@ enum CFE_ES_PerfMode_t { CFE_ES_PERF_MAX_MODES }; -typedef struct { - uint32 DataToWrite; - uint32 ChildID; - char DataFileName[OS_MAX_PATH_LEN]; - int32 DataFileDescriptor; -} CFE_ES_PerfLogDump_t; +/* + * Perflog Dump Background Job states + * + * Writing performance log data is now handled by a state machine that runs + * as a background job in Executive services. When a performance log dump is + * pending, each iteration of the state machine performs a limited amount of + * work. Each iteration resumes work where the last iteration left off. + */ +typedef enum +{ + CFE_ES_PerfDumpState_IDLE, /* Placeholder for idle, no action */ + CFE_ES_PerfDumpState_INIT, /* Placeholder for entry/init, no action */ + CFE_ES_PerfDumpState_OPEN_FILE, /* Opening of the output file */ + CFE_ES_PerfDumpState_DELAY, /* Wait-state to ensure in-progress writes are finished */ + CFE_ES_PerfDumpState_LOCK_DATA, /* Locking of the global data structure */ + CFE_ES_PerfDumpState_WRITE_FS_HDR, /* Write the CFE FS file header */ + CFE_ES_PerfDumpState_WRITE_PERF_METADATA, /* Write the Perf global metadata */ + CFE_ES_PerfDumpState_WRITE_PERF_ENTRIES, /* Write the Perf Log entries (throttled) */ + CFE_ES_PerfDumpState_CLEANUP, /* Placeholder for cleanup, no action */ + CFE_ES_PerfDumpState_UNLOCK_DATA, /* Unlocking of the global data structure */ + CFE_ES_PerfDumpState_CLOSE_FILE, /* Closing of the output file */ + CFE_ES_PerfDumpState_MAX /* Placeholder for last state, no action, always last */ +} CFE_ES_PerfDumpState_t; + +/* + * Performance log dump state structure + * + * This structure is stored in global memory and keeps the state + * of the performance log dump from one iteration to the next. + * + * When state is IDLE, the background task does nothing and does not + * access or update any other members. + * + * The first state transition (IDLE->INIT) is triggered via ES command, + * where the command processor sets the PendingState. + * + * Once state is non-IDLE, the structure becomes owned by the background + * task. It will progress through the remainder of the state machine, + * eventually arriving back at IDLE when the request is completed. + */ +typedef struct +{ + CFE_ES_PerfDumpState_t CurrentState; /* the current state of the job */ + CFE_ES_PerfDumpState_t PendingState; /* the pending/next state, if transitioning */ + + char DataFileName[OS_MAX_PATH_LEN]; /* output file name from dump command */ + int32 FileDesc; /* file descriptor for writing */ + uint32 WorkCredit; /* accumulator based on the passage of time */ + uint32 StateCounter; /* number of blocks/items left in current state */ + uint32 DataPos; /* last position within the Perf Log */ + uint32 FileSize; /* Total file size, for progress reporing in telemetry */ +} CFE_ES_PerfDumpGlobal_t; + +/* + * Helper function to obtain the progress/remaining items from + * the background task that is writing the performance log data + * + * This is no longer just simply reading a single value from a struct, + * as it depends on the state of the overall process. The return value + * from this should mimic the value which was historically + * returned in the ES telemetry to report progress on this task. + * + * Foreground tasks/telemetry code shouldn't directly "peek" + * into data structures which it does not own. + */ +uint32 CFE_ES_GetPerfLogDumpRemaining(void); -extern CFE_ES_PerfLogDump_t CFE_ES_PerfLogDumpStatus; +/* + * Implementation of the background state machine for writing + * performance log data. + */ +bool CFE_ES_RunPerfLogDump(uint32 ElapsedTime, void *Arg); #endif /* _cfe_es_perf_ */ diff --git a/fsw/cfe-core/src/es/cfe_es_start.c b/fsw/cfe-core/src/es/cfe_es_start.c index ed33af60a..73411dbf6 100644 --- a/fsw/cfe-core/src/es/cfe_es_start.c +++ b/fsw/cfe-core/src/es/cfe_es_start.c @@ -131,6 +131,32 @@ void CFE_ES_Main(uint32 StartType, uint32 StartSubtype, uint32 ModeId, const cha return; } /* end if */ + /* + ** Also Create the ES Performance Data Mutex + ** This is to separately protect against concurrent writes to the global performance log data + */ + ReturnCode = OS_MutSemCreate(&CFE_ES_Global.PerfDataMutex, "ES_PERF_MUTEX", 0); + if (ReturnCode != OS_SUCCESS) + { + CFE_ES_SysLogWrite_Unsync("ES Startup: Error: ES Performance Data Mutex could not be created. RC=0x%08X\n", + (unsigned int)ReturnCode); + + /* + ** Delay to allow the message to be read + */ + OS_TaskDelay(CFE_ES_PANIC_DELAY); + + /* + ** cFE Cannot continue to start up. + */ + CFE_PSP_Panic(CFE_PSP_PANIC_STARTUP_SEM); + + /* + * Normally CFE_PSP_Panic() will not return but it will under UT + */ + return; + } + /* ** Announce the startup */ diff --git a/fsw/cfe-core/src/es/cfe_es_task.c b/fsw/cfe-core/src/es/cfe_es_task.c index de746cfc3..bb5dc5fdf 100644 --- a/fsw/cfe-core/src/es/cfe_es_task.c +++ b/fsw/cfe-core/src/es/cfe_es_task.c @@ -61,10 +61,10 @@ #define CFE_ES_PERF_FILTERMASK_INT_SIZE (sizeof(CFE_ES_ResetDataPtr->Perf.MetaData.FilterMask) / sizeof(uint32)) #define CFE_ES_PERF_FILTERMASK_EXT_SIZE (sizeof(CFE_ES_TaskData.HkPacket.Payload.PerfFilterMask) / sizeof(uint32)) -/* -** This define should be put in the OS API headers -- Right now it matches what the OS API uses +/* +** This define should be put in the OS API headers -- Right now it matches what the OS API uses */ -#define OS_MAX_PRIORITY 255 +#define OS_MAX_PRIORITY 255 /* ** Executive Services (ES) task global data. @@ -83,7 +83,7 @@ void CFE_ES_TaskMain(void) uint32 TimeOut = CFE_PLATFORM_ES_APP_SCAN_RATE; uint32 AppRunStatus = CFE_ES_RunStatus_APP_RUN; - + /* ** Performance Time Stamp Entry */ @@ -99,13 +99,13 @@ void CFE_ES_TaskMain(void) ** Create a syslog entry */ CFE_ES_WriteToSysLog("ES:Application Init Failed,RC=0x%08X\n", (unsigned int)Status); - + /* - ** Allow Core App to Exit + ** Allow Core App to Exit */ AppRunStatus = CFE_ES_RunStatus_CORE_APP_INIT_ERROR; - + } /* end if */ /* @@ -128,7 +128,7 @@ void CFE_ES_TaskMain(void) ** use the RunLoop call. */ CFE_ES_IncrementTaskCounter(); - + /* ** Performance Time Stamp Exit */ @@ -159,7 +159,7 @@ void CFE_ES_TaskMain(void) ** Process Software Bus message. */ CFE_ES_TaskPipe(CFE_ES_TaskData.MsgPtr); - + /* ** Scan the App Table for changes after processing a command */ @@ -168,24 +168,24 @@ void CFE_ES_TaskMain(void) else { /* - ** SB Error: Write a SysLog Message + ** SB Error: Write a SysLog Message */ CFE_ES_WriteToSysLog("ES:Error reading cmd pipe,RC=0x%08X\n",(unsigned int)Status); /* - ** Allow Core App to Exit + ** Allow Core App to Exit */ AppRunStatus = CFE_ES_RunStatus_CORE_APP_RUNTIME_ERROR; } /* end if */ - - } /* end while */ - + + } /* end while */ + /* ** Performance Time Stamp Exit */ CFE_ES_PerfLogExit(CFE_MISSION_ES_MAIN_PERF_ID); - + /* ** Exit the application, CFE_ES_ExitApp will not return. */ @@ -216,7 +216,7 @@ int32 CFE_ES_TaskInit(void) { CFE_ES_WriteToSysLog("ES:Call to CFE_ES_RegisterApp Failed, RC = 0x%08X\n", (unsigned int)Status); return(Status); - } + } /* ** Initialize task command execution counters @@ -232,7 +232,7 @@ int32 CFE_ES_TaskInit(void) CFE_ES_TaskData.LimitHK = 2; CFE_ES_TaskData.LimitCmd = 4; - + /* ** Initialize systemlog to default mode */ @@ -266,7 +266,7 @@ int32 CFE_ES_TaskInit(void) /* ** Initialize memory pool statistics telemetry packet */ - CFE_SB_InitMsg(&CFE_ES_TaskData.MemStatsPacket, CFE_ES_MEMSTATS_TLM_MID, + CFE_SB_InitMsg(&CFE_ES_TaskData.MemStatsPacket, CFE_ES_MEMSTATS_TLM_MID, sizeof(CFE_ES_TaskData.MemStatsPacket), true); /* @@ -278,7 +278,7 @@ int32 CFE_ES_TaskInit(void) CFE_ES_WriteToSysLog("ES:Cannot Create SB Pipe, RC = 0x%08X\n", (unsigned int)Status); return(Status); } - + /* ** Subscribe to Housekeeping request commands */ @@ -303,12 +303,12 @@ int32 CFE_ES_TaskInit(void) /* ** Compute the CRC for the cfe core code segment and place - ** in ES Housekeeping pkt. + ** in ES Housekeeping pkt. */ Status = CFE_PSP_GetCFETextSegmentInfo( &CfeSegmentAddr, &SizeofCfeSegment); - + if ( Status == CFE_PSP_SUCCESS ) - { + { CFE_ES_TaskData.HkPacket.Payload.CFECoreChecksum = CFE_ES_CalculateCRC( (void *)(CfeSegmentAddr), SizeofCfeSegment, 0, CFE_MISSION_ES_DEFAULT_CRC); } @@ -339,12 +339,12 @@ int32 CFE_ES_TaskInit(void) { CFE_ES_WriteToSysLog("ES:Error sending init event:RC=0x%08X\n", (unsigned int)Status); return(Status); - } + } Status = CFE_EVS_SendEvent(CFE_ES_INITSTATS_INF_EID, CFE_EVS_EventType_INFORMATION, "Versions:cFE %d.%d.%d.%d, OSAL %d.%d.%d.%d, PSP %d.%d.%d.%d, chksm %d", - CFE_MAJOR_VERSION,CFE_MINOR_VERSION,CFE_REVISION,CFE_MISSION_REV, + CFE_MAJOR_VERSION,CFE_MINOR_VERSION,CFE_REVISION,CFE_MISSION_REV, OS_MAJOR_VERSION,OS_MINOR_VERSION,OS_REVISION,OS_MISSION_REV, CFE_PSP_MAJOR_VERSION,CFE_PSP_MINOR_VERSION,CFE_PSP_REVISION,CFE_PSP_MISSION_REV, (int)CFE_ES_TaskData.HkPacket.Payload.CFECoreChecksum); @@ -398,9 +398,20 @@ int32 CFE_ES_TaskInit(void) return(Status); } + /* + * Initialize the "background task" which is a low priority child task + * devoted to maintence duties that do not need to execute on a + * strict/precise schedule. + */ + Status = CFE_ES_BackgroundInit(); + if ( Status != CFE_SUCCESS ) + { + CFE_ES_WriteToSysLog("ES:Error initializing background task:RC=0x%08X\n", (unsigned int)Status); + return(Status); + } return(CFE_SUCCESS); - + } /* End of CFE_ES_TaskInit() */ @@ -654,7 +665,7 @@ int32 CFE_ES_HousekeepingCmd(const CCSDS_CommandPacket_t *data) CFE_ES_TaskData.HkPacket.Payload.ERLogIndex = CFE_ES_ResetDataPtr->ERLogIndex; CFE_ES_TaskData.HkPacket.Payload.ERLogEntries = CFE_ES_ResetDataPtr->ERLogEntries; - + CFE_ES_TaskData.HkPacket.Payload.RegisteredCoreApps = CFE_ES_Global.RegisteredCoreApps; CFE_ES_TaskData.HkPacket.Payload.RegisteredExternalApps = CFE_ES_Global.RegisteredExternalApps; CFE_ES_TaskData.HkPacket.Payload.RegisteredTasks = CFE_ES_Global.RegisteredTasks; @@ -672,7 +683,7 @@ int32 CFE_ES_HousekeepingCmd(const CCSDS_CommandPacket_t *data) CFE_ES_TaskData.HkPacket.Payload.PerfDataStart = CFE_ES_ResetDataPtr->Perf.MetaData.DataStart; CFE_ES_TaskData.HkPacket.Payload.PerfDataEnd = CFE_ES_ResetDataPtr->Perf.MetaData.DataEnd; CFE_ES_TaskData.HkPacket.Payload.PerfDataCount = CFE_ES_ResetDataPtr->Perf.MetaData.DataCount; - CFE_ES_TaskData.HkPacket.Payload.PerfDataToWrite = CFE_ES_PerfLogDumpStatus.DataToWrite; + CFE_ES_TaskData.HkPacket.Payload.PerfDataToWrite = CFE_ES_GetPerfLogDumpRemaining(); /* * Fill out the perf trigger/filter mask objects @@ -763,10 +774,10 @@ int32 CFE_ES_NoopCmd(const CFE_ES_Noop_t *Cmd) CFE_ES_TaskData.CommandCounter++; CFE_EVS_SendEvent(CFE_ES_NOOP_INF_EID, CFE_EVS_EventType_INFORMATION, "No-op command. Versions:cFE %d.%d.%d.%d, OSAL %d.%d.%d.%d, PSP %d.%d.%d.%d", - CFE_MAJOR_VERSION,CFE_MINOR_VERSION,CFE_REVISION,CFE_MISSION_REV, + CFE_MAJOR_VERSION,CFE_MINOR_VERSION,CFE_REVISION,CFE_MISSION_REV, OS_MAJOR_VERSION,OS_MINOR_VERSION,OS_REVISION,OS_MISSION_REV, CFE_PSP_MAJOR_VERSION,CFE_PSP_MINOR_VERSION,CFE_PSP_REVISION,CFE_PSP_MISSION_REV); - + return CFE_SUCCESS; } /* End of CFE_ES_NoopCmd() */ @@ -948,7 +959,7 @@ int32 CFE_ES_StartAppCmd(const CFE_ES_StartApp_t *data) Result = CFE_ES_AppCreate(&AppID, LocalFile, LocalEntryPt, LocalAppName, - (uint32) cmd->Priority, + (uint32) cmd->Priority, (uint32) cmd->StackSize, (uint32) cmd->ExceptionAction); @@ -1261,7 +1272,7 @@ int32 CFE_ES_QueryAllCmd(const CFE_ES_QueryAll_t *data) { if(CFE_ES_Global.AppTable[i].AppState != CFE_ES_AppState_UNDEFINED) { - /* + /* ** zero out the local entry */ memset(&AppInfo,0,sizeof(CFE_ES_AppInfo_t)); @@ -1386,7 +1397,7 @@ int32 CFE_ES_QueryAllTasksCmd(const CFE_ES_QueryAllTasks_t *data) { if(CFE_ES_Global.TaskTable[i].RecordUsed != false) { - /* + /* ** zero out the local entry */ memset(&TaskInfo,0,sizeof(CFE_ES_TaskInfo_t)); @@ -1618,12 +1629,12 @@ int32 CFE_ES_ERLogDump(const char *Filename) CFE_FS_InitHeader(&FileHdr, CFE_ES_ER_LOG_DESC, CFE_FS_SubType_ES_ERLOG); /* write the cFE header to the file */ - WriteStat = CFE_FS_WriteHeader(fd, &FileHdr); + WriteStat = CFE_FS_WriteHeader(fd, &FileHdr); if(WriteStat != sizeof(CFE_FS_Header_t)) { CFE_ES_FileWriteByteCntErr(Filename,sizeof(CFE_FS_Header_t),WriteStat); OS_close(fd); - return CFE_ES_FILE_IO_ERR; + return CFE_ES_FILE_IO_ERR; }/* end if */ FileSize = WriteStat; @@ -1634,7 +1645,7 @@ int32 CFE_ES_ERLogDump(const char *Filename) CFE_EVS_SendEvent(CFE_ES_RST_ACCESS_EID, CFE_EVS_EventType_ERROR, "Error accessing ER Log,%s not written. RC = 0x%08X",Filename,(unsigned int)BspStat); OS_close(fd); - return CFE_ES_RST_ACCESS_ERR; + return CFE_ES_RST_ACCESS_ERR; }/* end if */ /* write a single ER log entry on each pass */ @@ -1645,11 +1656,11 @@ int32 CFE_ES_ERLogDump(const char *Filename) { CFE_ES_FileWriteByteCntErr(Filename,sizeof(CFE_ES_ERLog_t),WriteStat); OS_close(fd); - return CFE_ES_FILE_IO_ERR; - }/* end if */ + return CFE_ES_FILE_IO_ERR; + }/* end if */ FileSize += WriteStat; ResetDataAddr+=sizeof(CFE_ES_ERLog_t); - }/* end for */ + }/* end for */ OS_close(fd); @@ -1714,16 +1725,16 @@ int32 CFE_ES_ResetPRCountCmd(const CFE_ES_ResetPRCount_t *data) CFE_ES_TaskData.CommandCounter++; return CFE_SUCCESS; -} /* End of CFE_ES_ResetPRCountCmd() */ +} /* End of CFE_ES_ResetPRCountCmd() */ -/* * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * */ -/* */ -/* CFE_ES_SetMaxPRCountCmd() -- Set Maximum Processor reset count */ -/* */ -/* * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * */ +/* * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * */ +/* */ +/* CFE_ES_SetMaxPRCountCmd() -- Set Maximum Processor reset count */ +/* */ +/* * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * */ int32 CFE_ES_SetMaxPRCountCmd(const CFE_ES_SetMaxPRCount_t *data) -{ +{ const CFE_ES_SetMaxPRCountCmd_Payload_t *cmd = &data->Payload; /* @@ -1740,16 +1751,16 @@ int32 CFE_ES_SetMaxPRCountCmd(const CFE_ES_SetMaxPRCount_t *data) CFE_ES_TaskData.CommandCounter++; return CFE_SUCCESS; -} /* End of CFE_ES_RestartCmd() */ +} /* End of CFE_ES_RestartCmd() */ -/* * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * */ -/* */ -/* CFE_ES_DeleteCDSCmd() -- Delete Specified Critical Data Store */ -/* */ -/* * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * */ +/* * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * */ +/* */ +/* CFE_ES_DeleteCDSCmd() -- Delete Specified Critical Data Store */ +/* */ +/* * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * */ int32 CFE_ES_DeleteCDSCmd(const CFE_ES_DeleteCDS_t *data) -{ +{ int32 Status; const CFE_ES_DeleteCDSCmd_Payload_t *cmd = &data->Payload; char LocalCdsName[CFE_ES_CDS_MAX_FULL_NAME_LEN]; @@ -1798,19 +1809,19 @@ int32 CFE_ES_DeleteCDSCmd(const CFE_ES_DeleteCDS_t *data) } return CFE_SUCCESS; -} /* End of CFE_ES_DeleteCDSCmd() */ +} /* End of CFE_ES_DeleteCDSCmd() */ -/* * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * */ -/* */ -/* CFE_ES_SendMemPoolStatsCmd() -- Telemeter Memory Pool Statistics */ +/* * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * */ /* */ -/* Note: The "Application" parameter of the */ +/* CFE_ES_SendMemPoolStatsCmd() -- Telemeter Memory Pool Statistics */ +/* */ +/* Note: The "Application" parameter of the */ /* CFE_ES_TlmPoolStats_t structure is not used. */ -/* */ -/* * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * */ +/* */ +/* * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * */ int32 CFE_ES_SendMemPoolStatsCmd(const CFE_ES_SendMemPoolStats_t *data) -{ +{ const CFE_ES_SendMemPoolStatsCmd_Payload_t *Cmd; CFE_ES_MemHandle_t MemHandle; bool ValidHandle; @@ -1848,13 +1859,13 @@ int32 CFE_ES_SendMemPoolStatsCmd(const CFE_ES_SendMemPoolStats_t *data) } return CFE_SUCCESS; -} /* End of CFE_ES_SendMemPoolStatsCmd() */ +} /* End of CFE_ES_SendMemPoolStatsCmd() */ -/* * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * */ -/* */ -/* CFE_ES_DumpCDSRegistryCmd() -- Dump CDS Registry to a file */ -/* */ -/* * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * */ +/* * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * */ +/* */ +/* CFE_ES_DumpCDSRegistryCmd() -- Dump CDS Registry to a file */ +/* */ +/* * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * */ int32 CFE_ES_DumpCDSRegistryCmd(const CFE_ES_DumpCDSRegistry_t *data) { @@ -1913,7 +1924,7 @@ int32 CFE_ES_DumpCDSRegistryCmd(const CFE_ES_DumpCDSRegistry_t *data) sizeof(CFE_ES_CDSRegDumpRec_t)); FileSize += Status; - NumEntries++; + NumEntries++; } /* Look at the next entry in the Registry */ @@ -1928,7 +1939,7 @@ int32 CFE_ES_DumpCDSRegistryCmd(const CFE_ES_DumpCDSRegistry_t *data) DumpFilename, (int)FileSize, (int)NumEntries); /* Increment Successful Command Counter */ - CFE_ES_TaskData.CommandCounter++; + CFE_ES_TaskData.CommandCounter++; } else { @@ -1937,8 +1948,8 @@ int32 CFE_ES_DumpCDSRegistryCmd(const CFE_ES_DumpCDSRegistry_t *data) "Error writing CDS Registry to '%s', Status=0x%08X", DumpFilename, (unsigned int)Status); - /* Increment Command Error Counter */ - CFE_ES_TaskData.CommandErrorCounter++; + /* Increment Command Error Counter */ + CFE_ES_TaskData.CommandErrorCounter++; } } else @@ -1948,8 +1959,8 @@ int32 CFE_ES_DumpCDSRegistryCmd(const CFE_ES_DumpCDSRegistry_t *data) "Error writing cFE File Header to '%s', Status=0x%08X", DumpFilename, (unsigned int)Status); - /* Increment Command Error Counter */ - CFE_ES_TaskData.CommandErrorCounter++; + /* Increment Command Error Counter */ + CFE_ES_TaskData.CommandErrorCounter++; } /* We are done outputting data to the dump file. Close it. */ @@ -1962,8 +1973,8 @@ int32 CFE_ES_DumpCDSRegistryCmd(const CFE_ES_DumpCDSRegistry_t *data) "Error creating CDS dump file '%s', Status=0x%08X", DumpFilename, (unsigned int)FileDescriptor); - /* Increment Command Error Counter */ - CFE_ES_TaskData.CommandErrorCounter++; + /* Increment Command Error Counter */ + CFE_ES_TaskData.CommandErrorCounter++; } return CFE_SUCCESS; @@ -1983,7 +1994,7 @@ void CFE_ES_FileWriteByteCntErr(const char *Filename,uint32 Requested,uint32 Act Filename,(unsigned int)Requested,(unsigned int)Actual); -}/* End of CFE_ES_FileWriteByteCntErr() */ +}/* End of CFE_ES_FileWriteByteCntErr() */ /************************/ /* End of File Comment */ diff --git a/fsw/cfe-core/src/es/cfe_es_task.h b/fsw/cfe-core/src/es/cfe_es_task.h index 250e1fd65..78b933261 100644 --- a/fsw/cfe-core/src/es/cfe_es_task.h +++ b/fsw/cfe-core/src/es/cfe_es_task.h @@ -28,7 +28,7 @@ ** Flight Software Branch C Coding Standard Version 1.0a ** cFE Flight Software Application Developers Guide ** -** Notes: +** Notes: ** */ /*************************************************************************/ @@ -43,6 +43,7 @@ #include "cfe_es_apps.h" #include "cfe_es_events.h" #include "cfe_es_msg.h" +#include "cfe_es_perf.h" /*************************************************************************/ @@ -97,7 +98,7 @@ typedef struct */ CFE_SB_MsgPtr_t MsgPtr; CFE_SB_PipeId_t CmdPipe; - + /* ** ES Task initialization data (not reported in housekeeping) */ @@ -107,6 +108,11 @@ typedef struct uint8 LimitHK; uint8 LimitCmd; + /* + * Persistent state data associated with performance log data file writes + */ + CFE_ES_PerfDumpGlobal_t BackgroundPerfDumpState; + } CFE_ES_TaskData_t; /* @@ -126,6 +132,14 @@ int32 CFE_ES_TaskInit(void); void CFE_ES_TaskPipe(CFE_SB_MsgPtr_t Msg); +/* + * Functions related to the ES background helper task for low-priority tasks + */ +int32 CFE_ES_BackgroundInit(void); +void CFE_ES_BackgroundTask(void); +void CFE_ES_BackgroundWakeup(void); +void CFE_ES_BackgroundCleanup(void); + /* ** ES Task message dispatch functions */ diff --git a/fsw/cfe-core/src/inc/cfe_es_events.h b/fsw/cfe-core/src/inc/cfe_es_events.h index 848ebf33b..78464a871 100644 --- a/fsw/cfe-core/src/inc/cfe_es_events.h +++ b/fsw/cfe-core/src/inc/cfe_es_events.h @@ -1013,23 +1013,6 @@ #define CFE_ES_PERF_STOPCMD_EID 60 -/** \brief 'Stop performance data cmd,Error creating child task RC=0x\%08X' -** \event 'Stop performance data cmd,Error creating child task RC=0x\%08X' -** -** \par Type: ERROR -** -** \par Cause: -** -** This event message is generated upon receipt of an unsuccessful Performance Data Stop -** Command after receiving the cFE Executive Services \link #CFE_ES_STOP_PERF_DATA_CC Stop -** Performance Analyzer Data Collection Command \endlink -** -** The \c 'RC' field specifies, in hex, the error code returned by the #CFE_ES_CreateChildTask API -** -**/ -#define CFE_ES_PERF_STOPCMD_ERR1_EID 61 - - /** \brief 'Stop performance data cmd ignored,perf data write in progress' ** \event 'Stop performance data cmd ignored,perf data write in progress' ** diff --git a/fsw/cfe-core/src/inc/private/cfe_es_perfdata_typedef.h b/fsw/cfe-core/src/inc/private/cfe_es_perfdata_typedef.h index ec730d59d..87dff302e 100644 --- a/fsw/cfe-core/src/inc/private/cfe_es_perfdata_typedef.h +++ b/fsw/cfe-core/src/inc/private/cfe_es_perfdata_typedef.h @@ -49,7 +49,14 @@ typedef struct { uint8 Spare[2]; uint32 TimerTicksPerSecond; uint32 TimerLow32Rollover; - uint32 State; + /* + * The "State" member is marked volatile to help + * ensure that an optimizing compiler does not rearrange + * or eliminate reads/writes of this value. It is read + * outside of any locking to determine whether or not + * the performance log function is enabled. + */ + volatile uint32 State; uint32 Mode; uint32 TriggerCount; uint32 DataStart; diff --git a/fsw/cfe-core/unit-test/es_UT.c b/fsw/cfe-core/unit-test/es_UT.c index e7a68cd17..065f3a061 100644 --- a/fsw/cfe-core/unit-test/es_UT.c +++ b/fsw/cfe-core/unit-test/es_UT.c @@ -293,6 +293,7 @@ void UtTest_Setup(void) UT_ADD_TEST(TestCDSMempool); UT_ADD_TEST(TestESMempool); UT_ADD_TEST(TestSysLog); + UT_ADD_TEST(TestBackground); #ifdef CFE_ARINC653 UT_ADD_TEST(TestStaticApp); @@ -2494,10 +2495,12 @@ void TestTask(void) /* Test task main process loop with a command pipe error */ ES_ResetUnitTest(); + CFE_ES_Global.TaskTable[1].RecordUsed = true; /* this is needed so CFE_ES_GetAppId works */ + CFE_ES_Global.TaskTable[1].AppId = 1; CFE_ES_TaskMain(); UT_Report(__FILE__, __LINE__, UT_PrintfIsInHistory(UT_OSP_MESSAGES[UT_OSP_COMMAND_PIPE]) && - UT_GetStubCount(UT_KEY(OS_printf)) == 1, + UT_GetStubCount(UT_KEY(OS_printf)) == 2, "CFE_ES_TaskMain", "Command pipe error"); @@ -2515,6 +2518,8 @@ void TestTask(void) /* Test task main process loop with bad checksum information */ ES_ResetUnitTest(); UT_SetDeferredRetcode(UT_KEY(CFE_PSP_GetCFETextSegmentInfo), 1, -1); + CFE_ES_Global.TaskTable[1].RecordUsed = true; /* this is needed so CFE_ES_GetAppId works */ + CFE_ES_Global.TaskTable[1].AppId = 1; UT_Report(__FILE__, __LINE__, CFE_ES_TaskInit() == CFE_SUCCESS && CFE_ES_TaskData.HkPacket.Payload.CFECoreChecksum == 0xFFFF, @@ -2523,6 +2528,8 @@ void TestTask(void) /* Test successful task main process loop */ ES_ResetUnitTest(); + CFE_ES_Global.TaskTable[1].RecordUsed = true; /* this is needed so CFE_ES_GetAppId works */ + CFE_ES_Global.TaskTable[1].AppId = 1; UT_Report(__FILE__, __LINE__, CFE_ES_TaskInit() == CFE_SUCCESS && CFE_ES_TaskData.HkPacket.Payload.CFECoreChecksum != 0xFFFF, @@ -2585,6 +2592,14 @@ void TestTask(void) "CFE_ES_TaskInit", "Version event send fail"); + /* Test task init with background init fail */ + ES_ResetUnitTest(); + UT_SetDeferredRetcode(UT_KEY(OS_BinSemCreate), 1, -7); + UT_Report(__FILE__, __LINE__, + CFE_ES_TaskInit() == -7, + "CFE_ES_TaskInit", + "Background init fail"); + /* Set the log mode to OVERWRITE; CFE_ES_TaskInit() sets SystemLogMode to * DISCARD, which can result in a log overflow depending on the value that * the index reaches during subsequent tests @@ -3810,8 +3825,6 @@ void TestPerf(void) CFE_ES_SetPerfTriggerMask_t PerfSetTrigMaskCmd; } CmdBuf; - extern CFE_ES_PerfLogDump_t CFE_ES_PerfLogDumpStatus; - #ifdef UT_VERBOSE UT_Text("Begin Test Performance Log\n"); #endif @@ -3897,7 +3910,10 @@ void TestPerf(void) /* Test performance data collection start with a file write in progress */ ES_ResetUnitTest(); memset(&CmdBuf, 0, sizeof(CmdBuf)); - CFE_ES_PerfLogDumpStatus.DataToWrite = 1; + /* clearing the BackgroundPerfDumpState will fully reset to initial state */ + memset(&CFE_ES_TaskData.BackgroundPerfDumpState, 0, + sizeof(CFE_ES_TaskData.BackgroundPerfDumpState)); + CFE_ES_TaskData.BackgroundPerfDumpState.CurrentState = CFE_ES_PerfDumpState_INIT; CmdBuf.PerfStartCmd.Payload.TriggerMode = CFE_ES_PERF_TRIGGER_START; UT_CallTaskPipe(CFE_ES_TaskPipe, &CmdBuf.Msg, sizeof(CmdBuf.PerfStartCmd), UT_TPID_CFE_ES_CMD_START_PERF_DATA_CC); @@ -3905,12 +3921,13 @@ void TestPerf(void) UT_EventIsInHistory(CFE_ES_PERF_STARTCMD_ERR_EID), "CFE_ES_StartPerfDataCmd", "Cannot collect performance data; write in progress"); - CFE_ES_PerfLogDumpStatus.DataToWrite = 0; /* Test performance data collection by sending another valid * start command */ ES_ResetUnitTest(); + memset(&CFE_ES_TaskData.BackgroundPerfDumpState, 0, + sizeof(CFE_ES_TaskData.BackgroundPerfDumpState)); memset(&CmdBuf, 0, sizeof(CmdBuf)); OS_TaskCreate(&TestObjId, "UT", NULL, NULL, 0, 0, 0); Id = ES_UT_OSALID_TO_ARRAYIDX(TestObjId); @@ -3925,11 +3942,12 @@ void TestPerf(void) /* Test successful performance data collection stop */ ES_ResetUnitTest(); + memset(&CFE_ES_TaskData.BackgroundPerfDumpState, 0, + sizeof(CFE_ES_TaskData.BackgroundPerfDumpState)); memset(&CmdBuf, 0, sizeof(CmdBuf)); OS_TaskCreate(&TestObjId, "UT", NULL, NULL, 0, 0, 0); Id = ES_UT_OSALID_TO_ARRAYIDX(TestObjId); CFE_ES_Global.TaskTable[Id].RecordUsed = true; - CFE_ES_PerfLogDumpStatus.DataToWrite = 0; UT_CallTaskPipe(CFE_ES_TaskPipe, &CmdBuf.Msg, sizeof(CmdBuf.PerfStopCmd), UT_TPID_CFE_ES_CMD_STOP_PERF_DATA_CC); UT_Report(__FILE__, __LINE__, @@ -3937,29 +3955,13 @@ void TestPerf(void) "CFE_ES_StopPerfDataCmd", "Stop collecting performance data"); - /* Test performance data collection stop with an OS create failure */ - ES_ResetUnitTest(); - UT_SetForceFail(UT_KEY(OS_creat), OS_ERROR); - UT_CallTaskPipe(CFE_ES_TaskPipe, &CmdBuf.Msg, sizeof(CmdBuf.PerfStopCmd), - UT_TPID_CFE_ES_CMD_STOP_PERF_DATA_CC); - UT_Report(__FILE__, __LINE__, - UT_EventIsInHistory(CFE_ES_PERF_LOG_ERR_EID), - "CFE_ES_StopPerfDataCmd", - "Stop performance data command; OS create fail"); - - /* Test performance data collection stop with an OS task create failure */ - ES_ResetUnitTest(); - UT_SetForceFail(UT_KEY(OS_TaskCreate), OS_ERROR); - UT_CallTaskPipe(CFE_ES_TaskPipe, &CmdBuf.Msg, sizeof(CmdBuf.PerfStopCmd), - UT_TPID_CFE_ES_CMD_STOP_PERF_DATA_CC); - UT_Report(__FILE__, __LINE__, - UT_EventIsInHistory(CFE_ES_PERF_STOPCMD_ERR1_EID), - "CFE_ES_StopPerfDataCmd", - "Stop performance data command; OS task create fail"); - /* Test successful performance data collection stop with a non-default file name */ ES_ResetUnitTest(); + + /* clearing the BackgroundPerfDumpState will fully reset to initial state */ + memset(&CFE_ES_TaskData.BackgroundPerfDumpState, 0, + sizeof(CFE_ES_TaskData.BackgroundPerfDumpState)); OS_TaskCreate(&TestObjId, "UT", NULL, NULL, 0, 0, 0); Id = ES_UT_OSALID_TO_ARRAYIDX(TestObjId); CFE_ES_Global.TaskTable[Id].RecordUsed = true; @@ -3974,7 +3976,7 @@ void TestPerf(void) /* Test performance data collection stop with a file write in progress */ ES_ResetUnitTest(); - CFE_ES_PerfLogDumpStatus.DataToWrite = 1; + CFE_ES_TaskData.BackgroundPerfDumpState.CurrentState = CFE_ES_PerfDumpState_INIT; UT_CallTaskPipe(CFE_ES_TaskPipe, &CmdBuf.Msg, sizeof(CmdBuf.PerfStopCmd), UT_TPID_CFE_ES_CMD_STOP_PERF_DATA_CC); UT_Report(__FILE__, __LINE__, @@ -4047,54 +4049,6 @@ void TestPerf(void) "CFE_ES_SetPerfTriggerMaskCmd", "Performance trigger mask command error; index out of range"); - /* Test successful performance log dump */ - ES_ResetUnitTest(); - CFE_ES_PerfLogDumpStatus.DataFileDescriptor = OS_open(NULL, 0, 0); - CFE_ES_PerfLogDump(); - UT_Report(__FILE__, __LINE__, - UT_EventIsInHistory(CFE_ES_PERF_DATAWRITTEN_EID) && - UT_GetStubCount(UT_KEY(OS_close)) == 1, - "CFE_ES_PerfLogDump", - "Performance log dump; success"); - - /* Test performance log dump with a cFE header write failure */ - ES_ResetUnitTest(); - CFE_ES_PerfLogDumpStatus.DataFileDescriptor = OS_open(NULL, 0, 0); - Perf->MetaData.DataCount = 7; - UT_SetDeferredRetcode(UT_KEY(OS_write), 4, sizeof(CFE_ES_PerfDataEntry_t)); - UT_SetDeferredRetcode(UT_KEY(CFE_FS_WriteHeader), 1, -1); - CFE_ES_PerfLogDump(); - UT_Report(__FILE__, __LINE__, - UT_EventIsInHistory(CFE_ES_FILEWRITE_ERR_EID) && - UT_GetStubCount(UT_KEY(OS_close)) == 1, - "CFE_ES_PerfLogDump", - "Performance log dump; cFE header write failed"); - - /* Test performance log dump with a metadata write failure */ - ES_ResetUnitTest(); - CFE_ES_PerfLogDumpStatus.DataFileDescriptor = OS_open(NULL, 0, 0); - Perf->MetaData.DataCount = 7; - UT_SetForceFail(UT_KEY(OS_creat), OS_ERROR); - UT_SetForceFail(UT_KEY(OS_write), OS_ERROR); - CFE_ES_PerfLogDump(); - UT_Report(__FILE__, __LINE__, - UT_EventIsInHistory(CFE_ES_FILEWRITE_ERR_EID) && - UT_GetStubCount(UT_KEY(OS_close)) == 1, - "CFE_ES_PerfLogDump", - "Performance log dump; metadata write failed"); - - /* Test performance log dump with a data write failure */ - ES_ResetUnitTest(); - CFE_ES_PerfLogDumpStatus.DataFileDescriptor = OS_open(NULL, 0, 0); - Perf->MetaData.DataCount = 7; - UT_SetDeferredRetcode(UT_KEY(OS_write), 4, sizeof(CFE_ES_PerfDataEntry_t) + 1); - CFE_ES_PerfLogDump(); - UT_Report(__FILE__, __LINE__, - UT_EventIsInHistory(CFE_ES_FILEWRITE_ERR_EID) && - UT_GetStubCount(UT_KEY(OS_close)) == 1, - "CFE_ES_PerfLogDump", - "Performance log dump; data write failed"); - /* Test successful addition of a new entry to the performance log */ ES_ResetUnitTest(); Perf->MetaData.State = CFE_ES_PERF_WAITING_FOR_TRIGGER; @@ -4275,6 +4229,97 @@ void TestPerf(void) !UT_EventIsInHistory(CFE_ES_PERF_TRIGMSKCMD_EID), "CFE_ES_SetPerfTriggerMaskCmd", "Invalid message length"); + + /* Test perf log dump state machine */ + /* Nominal call 1 - should go through up to the DELAY state */ + ES_ResetUnitTest(); + memset(&CFE_ES_TaskData.BackgroundPerfDumpState, 0, + sizeof(CFE_ES_TaskData.BackgroundPerfDumpState)); + CFE_ES_TaskData.BackgroundPerfDumpState.PendingState = CFE_ES_PerfDumpState_INIT; + CFE_ES_RunPerfLogDump(1000, &CFE_ES_TaskData.BackgroundPerfDumpState); + UtAssert_True(CFE_ES_TaskData.BackgroundPerfDumpState.CurrentState == CFE_ES_PerfDumpState_DELAY, + "CFE_ES_RunPerfLogDump - CFE_ES_TaskData.BackgroundPerfDumpState.CurrentState (%d) == DELAY (%d)", + (int)CFE_ES_TaskData.BackgroundPerfDumpState.CurrentState, (int)CFE_ES_PerfDumpState_DELAY); + UtAssert_True(UT_GetStubCount(UT_KEY(OS_creat)) == 1, "CFE_ES_RunPerfLogDump - OS_creat() called"); + + /* Nominal call 2 - should go through up to the remainder of states, back to IDLE */ + CFE_ES_RunPerfLogDump(1000, &CFE_ES_TaskData.BackgroundPerfDumpState); + UtAssert_True(CFE_ES_TaskData.BackgroundPerfDumpState.CurrentState == CFE_ES_PerfDumpState_IDLE, + "CFE_ES_RunPerfLogDump - CFE_ES_TaskData.BackgroundPerfDumpState.CurrentState (%d) == IDLE (%d)", + (int)CFE_ES_TaskData.BackgroundPerfDumpState.CurrentState, (int)CFE_ES_PerfDumpState_IDLE); + UtAssert_True(UT_GetStubCount(UT_KEY(OS_close)) == 1, "CFE_ES_RunPerfLogDump - OS_close() called"); + + /* Test a failure to open the output file */ + /* This should go immediately back to idle, and generate CFE_ES_PERF_LOG_ERR_EID */ + ES_ResetUnitTest(); + memset(&CFE_ES_TaskData.BackgroundPerfDumpState, 0, + sizeof(CFE_ES_TaskData.BackgroundPerfDumpState)); + CFE_ES_TaskData.BackgroundPerfDumpState.PendingState = CFE_ES_PerfDumpState_INIT; + UT_SetForceFail(UT_KEY(OS_creat), -10); + CFE_ES_RunPerfLogDump(1000, &CFE_ES_TaskData.BackgroundPerfDumpState); + UtAssert_True(CFE_ES_TaskData.BackgroundPerfDumpState.CurrentState == CFE_ES_PerfDumpState_IDLE, + "CFE_ES_RunPerfLogDump - OS create fail, CFE_ES_TaskData.BackgroundPerfDumpState.CurrentState (%d) == IDLE (%d)", + (int)CFE_ES_TaskData.BackgroundPerfDumpState.CurrentState, (int)CFE_ES_PerfDumpState_IDLE); + UtAssert_True(UT_EventIsInHistory(CFE_ES_PERF_LOG_ERR_EID), + "CFE_ES_RunPerfLogDump - OS create fail, generated CFE_ES_PERF_LOG_ERR_EID"); + + /* Test a failure to write to the output file */ + ES_ResetUnitTest(); + memset(&CFE_ES_TaskData.BackgroundPerfDumpState, 0, + sizeof(CFE_ES_TaskData.BackgroundPerfDumpState)); + UT_SetForceFail(UT_KEY(OS_write), -10); + CFE_ES_TaskData.BackgroundPerfDumpState.PendingState = CFE_ES_PerfDumpState_INIT; + CFE_ES_RunPerfLogDump(1000, &CFE_ES_TaskData.BackgroundPerfDumpState); + UtAssert_True(CFE_ES_TaskData.BackgroundPerfDumpState.CurrentState == CFE_ES_PerfDumpState_DELAY, + "CFE_ES_RunPerfLogDump - OS_write fail, CFE_ES_TaskData.BackgroundPerfDumpState.CurrentState (%d) == DELAY (%d)", + (int)CFE_ES_TaskData.BackgroundPerfDumpState.CurrentState, (int)CFE_ES_PerfDumpState_DELAY); + + /* This will trigger the OS_write() failure, which should go through up to the remainder of states, back to IDLE */ + CFE_ES_RunPerfLogDump(1000, &CFE_ES_TaskData.BackgroundPerfDumpState); + UtAssert_True(CFE_ES_TaskData.BackgroundPerfDumpState.CurrentState == CFE_ES_PerfDumpState_IDLE, + "CFE_ES_RunPerfLogDump - OS_write fail, CFE_ES_TaskData.BackgroundPerfDumpState.CurrentState (%d) == IDLE (%d)", + (int)CFE_ES_TaskData.BackgroundPerfDumpState.CurrentState, (int)CFE_ES_PerfDumpState_IDLE); + UtAssert_True(UT_EventIsInHistory(CFE_ES_FILEWRITE_ERR_EID), + "CFE_ES_RunPerfLogDump - OS_write fail, generated CFE_ES_FILEWRITE_ERR_EID"); + + + /* Test the ability of the file writer to handle the "wrap around" from the end of + * the perflog buffer back to the beginning. Just need to set up the metadata + * so that the writing position is toward the end of the buffer. + */ + ES_ResetUnitTest(); + memset(&CFE_ES_TaskData.BackgroundPerfDumpState, 0, + sizeof(CFE_ES_TaskData.BackgroundPerfDumpState)); + CFE_ES_TaskData.BackgroundPerfDumpState.FileDesc = OS_creat("UT", OS_WRITE_ONLY); + CFE_ES_TaskData.BackgroundPerfDumpState.CurrentState = CFE_ES_PerfDumpState_WRITE_PERF_ENTRIES; + CFE_ES_TaskData.BackgroundPerfDumpState.PendingState = CFE_ES_PerfDumpState_WRITE_PERF_ENTRIES; + CFE_ES_TaskData.BackgroundPerfDumpState.DataPos = CFE_PLATFORM_ES_PERF_DATA_BUFFER_SIZE - 2; + CFE_ES_TaskData.BackgroundPerfDumpState.StateCounter = 4; + CFE_ES_RunPerfLogDump(1000, &CFE_ES_TaskData.BackgroundPerfDumpState); + /* check that the wraparound occurred */ + UtAssert_True(CFE_ES_TaskData.BackgroundPerfDumpState.DataPos == 2, + "CFE_ES_RunPerfLogDump - wraparound, DataPos (%u) == 2", + (unsigned int)CFE_ES_TaskData.BackgroundPerfDumpState.DataPos); + /* should have written 4 entries to the log */ + UtAssert_True(CFE_ES_TaskData.BackgroundPerfDumpState.FileSize == sizeof(CFE_ES_PerfDataEntry_t) * 4, + "CFE_ES_RunPerfLogDump - wraparound, FileSize (%u) == sizeof(CFE_ES_PerfDataEntry_t) * 4", + (unsigned int)CFE_ES_TaskData.BackgroundPerfDumpState.FileSize); + + /* Confirm that the "CFE_ES_GetPerfLogDumpRemaining" function works. + * This requires that the state is not idle, in order to get nonzero results. + */ + ES_ResetUnitTest(); + memset(&CFE_ES_TaskData.BackgroundPerfDumpState, 0, + sizeof(CFE_ES_TaskData.BackgroundPerfDumpState)); + CFE_ES_TaskData.BackgroundPerfDumpState.FileDesc = OS_creat("UT", OS_WRITE_ONLY); + CFE_ES_TaskData.BackgroundPerfDumpState.CurrentState = CFE_ES_PerfDumpState_WRITE_PERF_METADATA; + CFE_ES_TaskData.BackgroundPerfDumpState.StateCounter = 10; + Perf->MetaData.DataCount = 100; + /* in states other than WRITE_PERF_ENTRIES, it should report the full size of the log */ + UtAssert_True(CFE_ES_GetPerfLogDumpRemaining() == 100, " CFE_ES_GetPerfLogDumpRemaining - Setup Phase"); + /* in WRITE_PERF_ENTRIES, it should report the StateCounter */ + CFE_ES_TaskData.BackgroundPerfDumpState.CurrentState = CFE_ES_PerfDumpState_WRITE_PERF_ENTRIES; + UtAssert_True(CFE_ES_GetPerfLogDumpRemaining() == 10, " CFE_ES_GetPerfLogDumpRemaining - Active Phase"); } void TestAPI(void) @@ -6911,6 +6956,59 @@ void TestSysLog(void) } +void TestBackground(void) +{ + int32 status; + + /* CFE_ES_BackgroundInit() with default setup + * causes CFE_ES_CreateChildTask to fail. + */ + ES_ResetUnitTest(); + status = CFE_ES_BackgroundInit(); + UtAssert_True(status == CFE_ES_ERR_APPID, "CFE_ES_BackgroundInit - CFE_ES_CreateChildTask failure (%08x)", (unsigned int)status); + + /* The CFE_ES_BackgroundCleanup() function has no conditionals - + * it just needs to be executed as part of this routine, + * and confirm that it deleted the semaphore. + */ + ES_ResetUnitTest(); + OS_BinSemCreate(&CFE_ES_Global.BackgroundTask.WorkSem, "UT", 0, 0); + CFE_ES_BackgroundCleanup(); + UtAssert_True(UT_GetStubCount(UT_KEY(OS_BinSemDelete)) == 1, "CFE_ES_BackgroundCleanup - OS_BinSemDelete called"); + + /* + * Test background task loop function + */ + ES_ResetUnitTest(); + UT_SetDeferredRetcode(UT_KEY(OS_TaskRegister), 1, -1); + CFE_ES_BackgroundTask(); + /* this has no return value, but this can ensure that a syslog/printf was generated */ + UtAssert_True(UT_GetStubCount(UT_KEY(OS_printf)) == 1, "CFE_ES_BackgroundTask - CFE_ES_RegisterChildTask failure"); + + /* + * When testing the background task loop, it is normally an infinite loop, + * so this is needed to set a condition for the loop to exit. + * + * This also sets a state so the background perf log dump will be "Active" to + * execute the code which counts the number of active jobs. + */ + ES_ResetUnitTest(); + memset(&CFE_ES_TaskData.BackgroundPerfDumpState, 0, + sizeof(CFE_ES_TaskData.BackgroundPerfDumpState)); + UT_SetForceFail(UT_KEY(OS_write), -10); + CFE_ES_TaskData.BackgroundPerfDumpState.CurrentState = CFE_ES_PerfDumpState_INIT; + UT_SetDeferredRetcode(UT_KEY(OS_BinSemTimedWait), 3, -4); + CFE_ES_BackgroundTask(); + /* this has no return value, but this can ensure that a syslog/printf was generated */ + UtAssert_True(UT_GetStubCount(UT_KEY(OS_printf)) == 1, "CFE_ES_BackgroundTask - Nominal"); + /* The number of jobs running should be 1 (perf log dump) */ + UtAssert_True(CFE_ES_Global.BackgroundTask.NumJobsRunning == 1, + "CFE_ES_BackgroundTask - Nominal, CFE_ES_Global.BackgroundTask.NumJobsRunning (%u) == 1", + (unsigned int)CFE_ES_Global.BackgroundTask.NumJobsRunning); +} + + + #ifdef CFE_ARINC653 void TestStaticApp(void) { diff --git a/fsw/cfe-core/unit-test/es_UT.h b/fsw/cfe-core/unit-test/es_UT.h index 4d302cf81..b597c7a1d 100644 --- a/fsw/cfe-core/unit-test/es_UT.h +++ b/fsw/cfe-core/unit-test/es_UT.h @@ -215,6 +215,23 @@ void TestShell(void); ******************************************************************************/ void TestTask(void); +/*****************************************************************************/ +/** +** \brief Performs tests of the background task contained in +** cfe_es_backgroundtask.c +** +** \par Description +** Gets Coverage on all lines/functions in this unit +** +** \par Assumptions, External Events, and Notes: +** None +** +** \returns +** This function does not return a value. +** +******************************************************************************/ +void TestBackground(void); + /*****************************************************************************/ /** ** \brief Performs tests on the functions that implement the software timing