This is an automated email from the ASF dual-hosted git repository. pnoltes pushed a commit to branch feature/scheduled_event_on_event_thread in repository https://gitbox.apache.org/repos/asf/celix.git
commit 6140f6a894cee3deeb0167e6b3fe8aa0313946a2 Author: Pepijn Noltes <[email protected]> AuthorDate: Sun Jun 25 18:45:14 2023 +0200 Test scheduled event processing log timeout. --- documents/framework.md | 35 ++--- .../framework/gtest/src/ScheduledEventTestSuite.cc | 155 ++++++++++++++------- libs/framework/include/celix_constants.h | 15 ++ libs/framework/src/celix_scheduled_event.c | 56 +++++--- libs/framework/src/celix_scheduled_event.h | 9 +- libs/framework/src/framework.c | 7 +- 6 files changed, 181 insertions(+), 96 deletions(-) diff --git a/documents/framework.md b/documents/framework.md index 01ca45da..4eb0b99d 100644 --- a/documents/framework.md +++ b/documents/framework.md @@ -259,20 +259,21 @@ So changing the environment variables after the framework is created will not ha The following framework properties are supported: -| Framework Property | Default Value | Description | -|-------------------------------------------|---------------|---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------| -| CELIX_FRAMEWORK_CACHE_DIR | ".cache" | The directory where the Apache Celix framework will store its data. | -| CELIX_FRAMEWORK_CACHE_USE_TMP_DIR | "false" | If true, the Apache Celix framework will use the system temp directory for the cache directory. | -| CELIX_FRAMEWORK_CLEAN_CACHE_DIR_ON_CREATE | "false" | If true, the Apache Celix framework will clean the cache directory on create. | -| CELIX_FRAMEWORK_FRAMEWORK_UUID | "" | The UUID of the Apache Celix framework. If not set, a random UUID will be generated. | -| CELIX_BUNDLES_PATH | "bundles" | The directories where the Apache Celix framework will search for bundles. Multiple directories can be provided separated by a colon. | -| CELIX_LOAD_BUNDLES_WITH_NODELETE | "false" | If true, the Apache Celix framework will load bundle libraries with the RTLD_NODELETE flags. Note for cmake build type Debug, the default is "true", otherwise the default is "false" | -| CELIX_FRAMEWORK_STATIC_EVENT_QUEUE_SIZE | "100" | The size of the static event queue. If more than 100 events in the queue are needed, dynamic memory allocation will be used. | -| CELIX_FRAMEWORK_AUTO_START_0 | "" | The bundles to install and start after the framework is started. Multiple bundles can be provided separated by a space. | -| CELIX_FRAMEWORK_AUTO_START_1 | "" | The bundles to install and start after the framework is started. Multiple bundles can be provided separated by a space. | -| CELIX_FRAMEWORK_AUTO_START_2 | "" | The bundles to install and start after the framework is started. Multiple bundles can be provided separated by a space. | -| CELIX_FRAMEWORK_AUTO_START_3 | "" | The bundles to install and start after the framework is started. Multiple bundles can be provided separated by a space. | -| CELIX_FRAMEWORK_AUTO_START_4 | "" | The bundles to install and start after the framework is started. Multiple bundles can be provided separated by a space. | -| CELIX_FRAMEWORK_AUTO_START_5 | "" | The bundles to install and start after the framework is started. Multiple bundles can be provided separated by a space. | -| CELIX_AUTO_INSTALL | "" | The bundles to install after the framework is started. Multiple bundles can be provided separated by a space. | -| CELIX_LOGGING_DEFAULT_ACTIVE_LOG_LEVEL | "info" | The default active log level for created log services. Possible values are "trace", "debug", "info", "warning", "error" and "fatal". | +| Framework Property | Default Value | Description | +|--------------------------------------------------------------|---------------|---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------| +| CELIX_FRAMEWORK_CACHE_DIR | ".cache" | The directory where the Apache Celix framework will store its data. | +| CELIX_FRAMEWORK_CACHE_USE_TMP_DIR | "false" | If true, the Apache Celix framework will use the system temp directory for the cache directory. | +| CELIX_FRAMEWORK_CLEAN_CACHE_DIR_ON_CREATE | "false" | If true, the Apache Celix framework will clean the cache directory on create. | +| CELIX_FRAMEWORK_FRAMEWORK_UUID | "" | The UUID of the Apache Celix framework. If not set, a random UUID will be generated. | +| CELIX_BUNDLES_PATH | "bundles" | The directories where the Apache Celix framework will search for bundles. Multiple directories can be provided separated by a colon. | +| CELIX_LOAD_BUNDLES_WITH_NODELETE | "false" | If true, the Apache Celix framework will load bundle libraries with the RTLD_NODELETE flags. Note for cmake build type Debug, the default is "true", otherwise the default is "false" | +| CELIX_FRAMEWORK_STATIC_EVENT_QUEUE_SIZE | "100" | The size of the static event queue. If more than 100 events in the queue are needed, dynamic memory allocation will be used. | +| CELIX_FRAMEWORK_AUTO_START_0 | "" | The bundles to install and start after the framework is started. Multiple bundles can be provided separated by a space. | +| CELIX_FRAMEWORK_AUTO_START_1 | "" | The bundles to install and start after the framework is started. Multiple bundles can be provided separated by a space. | +| CELIX_FRAMEWORK_AUTO_START_2 | "" | The bundles to install and start after the framework is started. Multiple bundles can be provided separated by a space. | +| CELIX_FRAMEWORK_AUTO_START_3 | "" | The bundles to install and start after the framework is started. Multiple bundles can be provided separated by a space. | +| CELIX_FRAMEWORK_AUTO_START_4 | "" | The bundles to install and start after the framework is started. Multiple bundles can be provided separated by a space. | +| CELIX_FRAMEWORK_AUTO_START_5 | "" | The bundles to install and start after the framework is started. Multiple bundles can be provided separated by a space. | +| CELIX_AUTO_INSTALL | "" | The bundles to install after the framework is started. Multiple bundles can be provided separated by a space. | +| CELIX_LOGGING_DEFAULT_ACTIVE_LOG_LEVEL | "info" | The default active log level for created log services. Possible values are "trace", "debug", "info", "warning", "error" and "fatal". | + | CELIX_ALLOWED_PROCESSING_TIME_FOR_SCHEDULED_EVENT_IN_SECONDS | "2" | The allowed processing time for scheduled events in seconds, if processing takes longer a warning message will be logged. | diff --git a/libs/framework/gtest/src/ScheduledEventTestSuite.cc b/libs/framework/gtest/src/ScheduledEventTestSuite.cc index b20b46bd..667973ec 100644 --- a/libs/framework/gtest/src/ScheduledEventTestSuite.cc +++ b/libs/framework/gtest/src/ScheduledEventTestSuite.cc @@ -25,15 +25,20 @@ class ScheduledEventTestSuite : public ::testing::Test { public: - ScheduledEventTestSuite() { fw = celix::createFramework({{"CELIX_LOGGING_DEFAULT_ACTIVE_LOG_LEVEL", "trace"}}); } - std::shared_ptr<celix::Framework> fw{}; - #ifdef __APPLE__ const int ALLOWED_ERROR_MARGIN_IN_MS = 500; #else const int ALLOWED_ERROR_MARGIN_IN_MS = 200; #endif + const double ALLOWED_PROCESSING_TIME_IN_SECONDS = 0.1; + + ScheduledEventTestSuite() { + fw = celix::createFramework({{"CELIX_LOGGING_DEFAULT_ACTIVE_LOG_LEVEL", "trace"}, + {CELIX_ALLOWED_PROCESSING_TIME_FOR_SCHEDULED_EVENT_IN_SECONDS, + std::to_string(ALLOWED_PROCESSING_TIME_IN_SECONDS)}}); + } + std::shared_ptr<celix::Framework> fw{}; /** * Wait for the given predicate to become true or the given time has elapsed. * @param predicate predicate to check. @@ -128,7 +133,7 @@ TEST_F(ScheduledEventTestSuite, ScheduledEventTest) { EXPECT_GE(eventId, 0); // Then count becomes 3 or more within the initial delay + 2 x internal and an allowed error margin (3x) - int allowedTimeInMs = 10 + (2 * 20) + (3*ALLOWED_ERROR_MARGIN_IN_MS); + int allowedTimeInMs = 10 + (2 * 20) + (3 * ALLOWED_ERROR_MARGIN_IN_MS); waitFor([&]() { return info.count.load() >= 3; }, std::chrono::milliseconds{allowedTimeInMs}); EXPECT_GE(info.count.load(), 3); @@ -248,8 +253,7 @@ TEST_F(ScheduledEventTestSuite, InvalidOptionsAndArgumentsTest) { EXPECT_EQ(scheduledEventId, -1); // celix_framework_waitForScheduledEvent with an invalid bndId should return CELIX_ILLEGAL_ARGUMENT - celix_status_t status = celix_framework_waitForScheduledEvent( - ctx->getFramework()->getCFramework(), 404, 1); + celix_status_t status = celix_framework_waitForScheduledEvent(ctx->getFramework()->getCFramework(), 404, 1); EXPECT_EQ(status, CELIX_ILLEGAL_ARGUMENT); } @@ -271,7 +275,8 @@ TEST_F(ScheduledEventTestSuite, WakeUpEventTest) { EXPECT_EQ(0, count.load()); // When the scheduled event is woken up - celix_status_t status = celix_bundleContext_wakeupScheduledEvent(fw->getFrameworkBundleContext()->getCBundleContext(), scheduledEventId); + celix_status_t status = celix_bundleContext_wakeupScheduledEvent( + fw->getFrameworkBundleContext()->getCBundleContext(), scheduledEventId); // Then the status is CELIX_SUCCESS ASSERT_EQ(CELIX_SUCCESS, status); @@ -289,7 +294,8 @@ TEST_F(ScheduledEventTestSuite, WakeUpEventTest) { EXPECT_NEAR(50, diff, ALLOWED_ERROR_MARGIN_IN_MS); // When waking up the scheduled event again - status = celix_bundleContext_wakeupScheduledEvent(fw->getFrameworkBundleContext()->getCBundleContext(), scheduledEventId); + status = celix_bundleContext_wakeupScheduledEvent(fw->getFrameworkBundleContext()->getCBundleContext(), + scheduledEventId); // Then the status is CELIX_SUCCESS ASSERT_EQ(CELIX_SUCCESS, status); @@ -361,7 +367,8 @@ TEST_F(ScheduledEventTestSuite, CxxScheduledEventTest) { auto start = std::chrono::steady_clock::now(); waitFor([&]() { return count.load() == 1; }, std::chrono::milliseconds{50 + ALLOWED_ERROR_MARGIN_IN_MS}); auto end = std::chrono::steady_clock::now(); - EXPECT_NEAR(50, std::chrono::duration_cast<std::chrono::milliseconds>(end - start).count(), ALLOWED_ERROR_MARGIN_IN_MS); + EXPECT_NEAR( + 50, std::chrono::duration_cast<std::chrono::milliseconds>(end - start).count(), ALLOWED_ERROR_MARGIN_IN_MS); EXPECT_EQ(1, count.load()); // When waking up the event @@ -444,11 +451,11 @@ TEST_F(ScheduledEventTestSuite, CxxOneShotScheduledEventTest) { EXPECT_FALSE(removed.load()); // And count will be increased within the initial delay (including some error margin) - waitFor([&]{return count.load() == 1;}, std::chrono::milliseconds{50 + ALLOWED_ERROR_MARGIN_IN_MS}); + waitFor([&] { return count.load() == 1; }, std::chrono::milliseconds{50 + ALLOWED_ERROR_MARGIN_IN_MS}); EXPECT_EQ(1, count.load()); // And the remove callback is called shortly after the initial delay, within the error margin - waitFor([&]{return removed.load();}, std::chrono::milliseconds{ALLOWED_ERROR_MARGIN_IN_MS}); + waitFor([&] { return removed.load(); }, std::chrono::milliseconds{ALLOWED_ERROR_MARGIN_IN_MS}); EXPECT_TRUE(removed.load()); // When waking up the event with a wait time of 1s @@ -490,11 +497,11 @@ TEST_F(ScheduledEventTestSuite, CxxOneShotScheduledEventRAIITest) { EXPECT_FALSE(removed.load()); // And count will be increased within the initial delay (including some error margin) - waitFor([&]{return count.load() == 1;}, std::chrono::milliseconds{50 + ALLOWED_ERROR_MARGIN_IN_MS}); + waitFor([&] { return count.load() == 1; }, std::chrono::milliseconds{50 + ALLOWED_ERROR_MARGIN_IN_MS}); EXPECT_EQ(1, count.load()); // And the remove callback is called shortly after the initial delay - waitFor([&]{return removed.load();}, std::chrono::milliseconds{10}); + waitFor([&] { return removed.load(); }, std::chrono::milliseconds{10}); EXPECT_TRUE(removed.load()); } @@ -504,23 +511,22 @@ TEST_F(ScheduledEventTestSuite, CxxCreateScheduledEventWithNoCallbackTest) { } TEST_F(ScheduledEventTestSuite, CxxCancelOneShotEventBeforeFiredTest) { - auto callback = []() { - FAIL() << "Should not be called"; - }; + auto callback = []() { FAIL() << "Should not be called"; }; - //Given a one shot scheduled event with an initial delay of 1s - auto event = fw->getFrameworkBundleContext()->scheduledEvent() + // Given a one shot scheduled event with an initial delay of 1s + auto event = fw->getFrameworkBundleContext() + ->scheduledEvent() .withInitialDelay(std::chrono::seconds{1}) .withCallback(callback) .build(); - //When the event is cancelled before the initial delay + // When the event is cancelled before the initial delay event.cancel(); - //And waiting a bit + // And waiting a bit std::this_thread::sleep_for(std::chrono::milliseconds{ALLOWED_ERROR_MARGIN_IN_MS}); - //Then the event is not fired and does not leak + // Then the event is not fired and does not leak } TEST_F(ScheduledEventTestSuite, RemoveScheduledEventAsync) { @@ -530,7 +536,7 @@ TEST_F(ScheduledEventTestSuite, RemoveScheduledEventAsync) { count->fetch_add(1); }; - //Given a scheduled event with am initial delay of 1ms + // Given a scheduled event with am initial delay of 1ms celix_scheduled_event_options_t opts{}; opts.initialDelayInSeconds = 0.01; opts.callbackData = &count; @@ -538,13 +544,13 @@ TEST_F(ScheduledEventTestSuite, RemoveScheduledEventAsync) { long eventId = celix_bundleContext_scheduleEvent(fw->getFrameworkBundleContext()->getCBundleContext(), &opts); EXPECT_GE(eventId, 0); - //When the event is removed async + // When the event is removed async celix_bundleContext_removeScheduledEventAsync(fw->getFrameworkBundleContext()->getCBundleContext(), eventId); - //And waiting longer than the initial delay, including some error margin + // And waiting longer than the initial delay, including some error margin std::this_thread::sleep_for(std::chrono::milliseconds{10 + ALLOWED_ERROR_MARGIN_IN_MS}); - //Then the event is not fired + // Then the event is not fired EXPECT_EQ(0, count.load()); } @@ -564,29 +570,31 @@ TEST_F(ScheduledEventTestSuite, WaitForScheduledEvent) { long eventId = celix_bundleContext_scheduleEvent(fw->getFrameworkBundleContext()->getCBundleContext(), &opts); EXPECT_GE(eventId, 0); - //When waiting for the event with a timeout longer than the initial delay + // When waiting for the event with a timeout longer than the initial delay auto status = celix_bundleContext_waitForScheduledEvent(fw->getFrameworkBundleContext()->getCBundleContext(), eventId, 1); - //Then the return status is success + // Then the return status is success EXPECT_EQ(CELIX_SUCCESS, status); - //And the event is fired + // And the event is fired EXPECT_EQ(1, count.load()); - //When waiting too short for the event - status = celix_bundleContext_waitForScheduledEvent(fw->getFrameworkBundleContext()->getCBundleContext(), eventId, 0.0001); + // When waiting too short for the event + status = celix_bundleContext_waitForScheduledEvent( + fw->getFrameworkBundleContext()->getCBundleContext(), eventId, 0.0001); - //Then the return status is timeout + // Then the return status is timeout EXPECT_EQ(ETIMEDOUT, status); - //When waiting for the event with a timeout longer than the interval - status = celix_bundleContext_waitForScheduledEvent(fw->getFrameworkBundleContext()->getCBundleContext(), eventId, 1); + // When waiting for the event with a timeout longer than the interval + status = + celix_bundleContext_waitForScheduledEvent(fw->getFrameworkBundleContext()->getCBundleContext(), eventId, 1); - //Then the return status is success + // Then the return status is success EXPECT_EQ(CELIX_SUCCESS, status); - //And the event is fired again + // And the event is fired again EXPECT_EQ(2, count.load()); celix_bundleContext_removeScheduledEvent(fw->getFrameworkBundleContext()->getCBundleContext(), eventId); @@ -594,38 +602,85 @@ TEST_F(ScheduledEventTestSuite, WaitForScheduledEvent) { TEST_F(ScheduledEventTestSuite, CxxWaitForScheduledEvent) { std::atomic<int> count{0}; - auto callback = [&count]() { - count.fetch_add(1); - }; + auto callback = [&count]() { count.fetch_add(1); }; // Given a scheduled event with an initial delay of 1ms and an interval of 1ms - auto event = fw->getFrameworkBundleContext()->scheduledEvent() + auto event = fw->getFrameworkBundleContext() + ->scheduledEvent() .withInitialDelay(std::chrono::milliseconds{10}) .withInterval(std::chrono::milliseconds{10}) .withCallback(callback) .build(); - //When waiting for the event with a timeout longer than the initial delay - auto success = event.waitFor(std::chrono::milliseconds{1000}); + // When waiting for the event with a timeout longer than the initial delay + auto success = event.waitFor(std::chrono::milliseconds{10 + ALLOWED_ERROR_MARGIN_IN_MS}); - //Then the return status is success + // Then the return status is success EXPECT_TRUE(success); - //And the event is fired + // And the event is fired EXPECT_EQ(1, count.load()); - //When waiting to short for the event - success = event.waitFor(std::chrono::microseconds {1}); + // When waiting to short for the event + success = event.waitFor(std::chrono::microseconds{1}); - //Then the return status is false (timeout) + // Then the return status is false (timeout) EXPECT_FALSE(success); - //When waiting for the event with a timeout longer than the interval - success = event.waitFor(std::chrono::milliseconds{1000}); + // When waiting for the event with a timeout longer than the interval + success = event.waitFor(std::chrono::milliseconds{10 + ALLOWED_ERROR_MARGIN_IN_MS}); - //Then the return status is success + // Then the return status is success EXPECT_TRUE(success); - //And the event is fired again + // And the event is fired again EXPECT_EQ(2, count.load()); } + +TEST_F(ScheduledEventTestSuite, ScheduledEventTimeoutLogTest) { + //Given a framework with a log callback that counts the number of warning log messages + std::atomic<int> logCount{0}; + auto logCallback = [](void* handle, celix_log_level_e level, const char*, const char*, int, const char* format, va_list args){ + std::atomic<int>& count = *static_cast<std::atomic<int>*>(handle); + if (level == CELIX_LOG_LEVEL_WARNING) { + count.fetch_add(1); + } + FILE* output = stdout; + if (level == CELIX_LOG_LEVEL_FATAL || level == CELIX_LOG_LEVEL_ERROR || level == CELIX_LOG_LEVEL_WARNING) { + output = stderr; + } + fprintf(output, "%s: ", celix_logLevel_toString(level)); + vfprintf(output, format, args); + fprintf(output, "\n"); + }; + celix_framework_setLogCallback(fw->getCFramework(), &logCount, logCallback); + + + //And a scheduled event with an initial delay of 1ms and an interval of 1ms that waits for 1ms in the callback + //and remove callback. + celix_scheduled_event_options_t opts{}; + opts.name = "Sleep while Processing and Removing Scheduled Event"; + opts.initialDelayInSeconds = 0.01; + opts.intervalInSeconds = 0.01; + opts.callback = [](void*){ + std::this_thread::sleep_for(std::chrono::milliseconds{100}); + }; + opts.removeCallback = [](void*){ + std::this_thread::sleep_for(std::chrono::milliseconds{100}); + }; + long eventId = celix_bundleContext_scheduleEvent(fw->getFrameworkBundleContext()->getCBundleContext(), &opts); + + //When the event is woken up + celix_bundleContext_wakeupScheduledEvent(fw->getFrameworkBundleContext()->getCBundleContext(), eventId); + + //Then the log callback is called with a warning log message within a error margin, because callback took too long + waitFor([&]{return logCount.load() == 1;}, std::chrono::milliseconds{ALLOWED_ERROR_MARGIN_IN_MS}); + EXPECT_EQ(1, logCount.load()); + + //When removing the event + celix_bundleContext_removeScheduledEvent(fw->getFrameworkBundleContext()->getCBundleContext(), eventId); + + //Then the log callback is called at least one more time with a warning log message, because callback took too long + //(note the logCount can be increased more than once, due to another processing thread) + EXPECT_GE(logCount.load(), 2); +} diff --git a/libs/framework/include/celix_constants.h b/libs/framework/include/celix_constants.h index 14a0a265..c2ad3a8c 100644 --- a/libs/framework/include/celix_constants.h +++ b/libs/framework/include/celix_constants.h @@ -322,6 +322,21 @@ extern "C" { */ #define CELIX_AUTO_INSTALL "CELIX_AUTO_INSTALL" +/*! + * @brief Celix framework environment property (named "CELIX_ALLOWED_PROCESSING_TIME_FOR_SCHEDULED_EVENT_IN_SECONDS") + * to configure the allowed processing time for a scheduled event callback or a remove callback before a warning + * log message is printed that the processing time is too long. + * Should be a double value in seconds. + */ +#define CELIX_ALLOWED_PROCESSING_TIME_FOR_SCHEDULED_EVENT_IN_SECONDS \ + "CELIX_ALLOWED_PROCESSING_TIME_FOR_SCHEDULED_EVENT_IN_SECONDS" + +/** + * @brief The default , in seconds, allowed processing time for a processing a scheduled event or a remove callback + * before a warning log message is printed. + */ +#define CELIX_DEFAULT_ALLOWED_PROCESSING_TIME_FOR_SCHEDULED_EVENT_IN_SECONDS 2.0 + #ifdef __cplusplus } #endif diff --git a/libs/framework/src/celix_scheduled_event.c b/libs/framework/src/celix_scheduled_event.c index b2d857db..42f85f0c 100644 --- a/libs/framework/src/celix_scheduled_event.c +++ b/libs/framework/src/celix_scheduled_event.c @@ -17,9 +17,11 @@ * under the License. */ +#include "celix_scheduled_event.h" + #include <assert.h> -#include "celix_scheduled_event.h" +#include "celix_constants.h" #include "celix_utils.h" /*! @@ -28,12 +30,6 @@ */ #define CELIX_SCHEDULED_EVENT_INTERVAL_ALLOW_ERROR_IN_SECONDS 0.000001 -/** - * @brief The timeout in seconds, before a log message is printed while waiting for a scheduled event to be processed. - */ -#define CELIX_SCHEDULED_EVENT_ERROR_LOG_TIMEOUT_IN_SECONDS 10.0 - - /** * @brief Default name for a scheduled event. */ @@ -59,9 +55,11 @@ struct celix_scheduled_event { long bndId; /**< The bundle id for the bundle that owns the scheduled event. */ char* eventName; /**< The name of the scheduled event. Will be CELIX_SCHEDULED_EVENT_DEFAULT_NAME if no name is provided during creation. */ - double initialDelayInSeconds; /**< The initial delay of the scheduled event in seconds. */ - double intervalInSeconds; /**< The interval of the scheduled event in seconds. */ - void* callbackData; /**< The data for the scheduled event callback. */ + double logTimeoutInSeconds; /**< The timeout, in seconds, before a log message is printed while waiting for a + scheduled event to be processed or removed. */ + double initialDelayInSeconds; /**< The initial delay of the scheduled event in seconds. */ + double intervalInSeconds; /**< The interval of the scheduled event in seconds. */ + void* callbackData; /**< The data for the scheduled event callback. */ void (*callback)(void* callbackData); /**< The callback function for the scheduled event. */ void* removedCallbackData; /**< The data for the scheduled event removed callback. */ void (*removedCallback)(void* removedCallbackData); /**< The callback function for the scheduled event removed @@ -79,7 +77,7 @@ struct celix_scheduled_event { call. */ }; -celix_scheduled_event_t* celix_scheduledEvent_create(celix_framework_logger_t* logger, +celix_scheduled_event_t* celix_scheduledEvent_create(celix_framework_t* fw, long bndId, long scheduledEventId, const char* providedEventName, @@ -93,10 +91,7 @@ celix_scheduled_event_t* celix_scheduledEvent_create(celix_framework_logger_t* l char* eventName = providedEventName == NULL ? (char*)CELIX_SCHEDULED_EVENT_DEFAULT_NAME : celix_utils_strdup(providedEventName); if (event == NULL || eventName == NULL) { - fw_log(logger, - CELIX_LOG_LEVEL_ERROR, - "Cannot add scheduled event for bundle id %li. Out of memory", - bndId); + fw_log(fw->logger, CELIX_LOG_LEVEL_ERROR, "Cannot add scheduled event for bundle id %li. Out of memory", bndId); free(event); if (eventName != CELIX_SCHEDULED_EVENT_DEFAULT_NAME) { free(eventName); @@ -105,10 +100,15 @@ celix_scheduled_event_t* celix_scheduledEvent_create(celix_framework_logger_t* l } event->scheduledEventId = scheduledEventId; - event->logger = logger; + event->logger = fw->logger; event->bndId = bndId; event->eventName = eventName; + event->logTimeoutInSeconds = + celix_framework_getConfigPropertyAsDouble(fw, + CELIX_ALLOWED_PROCESSING_TIME_FOR_SCHEDULED_EVENT_IN_SECONDS, + CELIX_DEFAULT_ALLOWED_PROCESSING_TIME_FOR_SCHEDULED_EVENT_IN_SECONDS, + NULL); event->initialDelayInSeconds = initialDelayInSeconds; event->intervalInSeconds = intervalInSeconds; event->callbackData = callbackData; @@ -166,9 +166,7 @@ const char* celix_scheduledEvent_getName(const celix_scheduled_event_t* event) { long celix_scheduledEvent_getId(const celix_scheduled_event_t* event) { return event->scheduledEventId; } -long celix_scheduledEvent_getBundleId(const celix_scheduled_event_t* event) { - return event->bndId; -} +long celix_scheduledEvent_getBundleId(const celix_scheduled_event_t* event) { return event->bndId; } bool celix_scheduledEvent_deadlineReached(celix_scheduled_event_t* event, const struct timespec* currentTime, @@ -201,14 +199,25 @@ void celix_scheduledEvent_process(celix_scheduled_event_t* event, const struct t event->bndId); assert(event->callback != NULL); + struct timespec start = celix_gettime(CLOCK_MONOTONIC); event->callback(event->callbackData); // note called outside of lock + struct timespec end = celix_gettime(CLOCK_MONOTONIC); celixThreadMutex_lock(&event->mutex); event->lastScheduledEventTime = *currentTime; event->callCount += 1; event->processForWakeup = false; - celixThreadCondition_broadcast(&event->cond); //for changed callCount + celixThreadCondition_broadcast(&event->cond); // for changed callCount celixThreadMutex_unlock(&event->mutex); + + if (celix_difftime(&start, &end) > event->logTimeoutInSeconds) { + fw_log(event->logger, + CELIX_LOG_LEVEL_WARNING, + "Processing scheduled event %s for bundle id %li took %f seconds", + event->eventName, + event->bndId, + celix_difftime(&start, &end)); + } } bool celix_scheduledEvent_isSingleShot(const celix_scheduled_event_t* event) { @@ -234,7 +243,8 @@ size_t celix_scheduledEvent_markForWakeup(celix_scheduled_event_t* event) { } void celix_scheduledEvent_waitForRemoved(celix_scheduled_event_t* event) { - struct timespec absLogTimeout = celixThreadCondition_getDelayedTime(CELIX_SCHEDULED_EVENT_ERROR_LOG_TIMEOUT_IN_SECONDS); + struct timespec absLogTimeout = + celixThreadCondition_getDelayedTime(event->logTimeoutInSeconds); celixThreadMutex_lock(&event->mutex); while (!event->isRemoved) { celix_status_t waitStatus = celixThreadCondition_waitUntil(&event->cond, &event->mutex, &absLogTimeout); @@ -245,7 +255,7 @@ void celix_scheduledEvent_waitForRemoved(celix_scheduled_event_t* event) { event->eventName, event->scheduledEventId, event->bndId); - absLogTimeout = celixThreadCondition_getDelayedTime(CELIX_SCHEDULED_EVENT_ERROR_LOG_TIMEOUT_IN_SECONDS); + absLogTimeout = celixThreadCondition_getDelayedTime(event->logTimeoutInSeconds); } } celixThreadMutex_unlock(&event->mutex); @@ -272,7 +282,7 @@ void celix_scheduledEvent_setRemoved(celix_scheduled_event_t* event) { } celixThreadMutex_lock(&event->mutex); event->isRemoved = true; - celixThreadCondition_broadcast(&event->cond); //for changed isRemoved + celixThreadCondition_broadcast(&event->cond); // for changed isRemoved celixThreadMutex_unlock(&event->mutex); } diff --git a/libs/framework/src/celix_scheduled_event.h b/libs/framework/src/celix_scheduled_event.h index 27ae6cc2..a9f92335 100644 --- a/libs/framework/src/celix_scheduled_event.h +++ b/libs/framework/src/celix_scheduled_event.h @@ -27,6 +27,9 @@ extern "C" { #endif +/** + * @brief A scheduled event is an event which is scheduled to be processed at a given initial delay and interval. + */ typedef struct celix_scheduled_event celix_scheduled_event_t; /** @@ -34,6 +37,7 @@ typedef struct celix_scheduled_event celix_scheduled_event_t; * * The scheduled event will be created with a use count of 1. * + * @param[in] fw The framework. * @param[in] bndId The bundle id for the bundle which the scheduled event is created. * @param[in] scheduledEventId The id of the scheduled event. * @param[in] eventName The name of the event. If NULL, CELIX_SCHEDULED_EVENT_DEFAULT_NAME is used. @@ -45,7 +49,7 @@ typedef struct celix_scheduled_event celix_scheduled_event_t; * @param[in] removedCallback The removed callback. * @return A new scheduled event or NULL if failed. */ -celix_scheduled_event_t* celix_scheduledEvent_create(celix_framework_logger_t* logger, +celix_scheduled_event_t* celix_scheduledEvent_create(celix_framework_t* fw, long bndId, long scheduledEventId, const char* providedEventName, @@ -134,7 +138,7 @@ bool celix_scheduledEvent_isMarkedForRemoval(celix_scheduled_event_t* event); /** * @brief Configure a scheduled event for a wakeup, so celix_scheduledEvent_deadlineReached will return true until * the event is processed. - * + * * @param[in] event The event to configure for wakeup. * @return The future call count of the event after the next processing is done. */ @@ -149,7 +153,6 @@ size_t celix_scheduledEvent_markForWakeup(celix_scheduled_event_t* event); */ celix_status_t celix_scheduledEvent_wait(celix_scheduled_event_t* event, double timeoutInSeconds); - /** * @brief Returns true if the event is marked for wakeup, the initial delay or interval deadline is reached or the * event is marked for removal for the given time. diff --git a/libs/framework/src/framework.c b/libs/framework/src/framework.c index 523e2a3b..d6d51eda 100644 --- a/libs/framework/src/framework.c +++ b/libs/framework/src/framework.c @@ -2621,7 +2621,7 @@ long celix_framework_scheduleEvent(celix_framework_t* fw, fw_log(fw->logger, CELIX_LOG_LEVEL_ERROR, "Cannot add scheduled event for non existing bundle id %li.", bndId); return -1; } - celix_scheduled_event_t* event = celix_scheduledEvent_create(fw->logger, + celix_scheduled_event_t* event = celix_scheduledEvent_create(fw, bndEntry->bndId, celix_framework_nextScheduledEventId(fw), eventName, @@ -2637,11 +2637,12 @@ long celix_framework_scheduleEvent(celix_framework_t* fw, return -1L; //error logged by celix_scheduledEvent_create } + long eventId = celix_scheduledEvent_getId(event); fw_log(fw->logger, CELIX_LOG_LEVEL_DEBUG, "Added scheduled event '%s' (id=%li) for bundle '%s' (id=%li).", celix_scheduledEvent_getName(event), - celix_scheduledEvent_getId(event), + eventId, celix_bundle_getSymbolicName(bndEntry->bnd), bndId); @@ -2650,7 +2651,7 @@ long celix_framework_scheduleEvent(celix_framework_t* fw, celixThreadCondition_broadcast(&fw->dispatcher.cond); //notify dispatcher thread for newly added scheduled event celixThreadMutex_unlock(&fw->dispatcher.mutex); - return celix_scheduledEvent_getId(event); + return eventId; } celix_status_t celix_framework_wakeupScheduledEvent(celix_framework_t* fw, long scheduledEventId) {
