Let we define new filter to check time duration and threshold to print.
It will be useful if we want to check duration of some API
Change-Id: Id1cb5878cb5daac6cf972f5f48f99d9b1695cf26
Signed-off-by: Eunki, Hong <eunkiki.hong@samsung.com>
utc-Dali-Internal-ActorRelayout.cpp
utc-Dali-Internal-ConstString.cpp
utc-Dali-Internal-Core.cpp
+ utc-Dali-Internal-Debug.cpp
utc-Dali-Internal-DummyMemoryPool.cpp
utc-Dali-Internal-FixedSizeMemoryPool.cpp
utc-Dali-Internal-FrustumCulling.cpp
--- /dev/null
+/*
+ * Copyright (c) 2024 Samsung Electronics Co., Ltd.
+ *
+ * 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.
+ *
+ */
+
+// Enable debug log for test coverage
+#define DEBUG_ENABLED 1
+
+#include <dali-test-suite-utils.h>
+#include <dali/public-api/dali-core.h>
+#include <stdlib.h>
+
+#include <iostream>
+
+// Internal headers are allowed here
+#include <dali/integration-api/debug.h>
+
+using namespace Dali;
+
+namespace
+{
+static Debug::DebugPriority gCapturedLogPriority;
+static std::string gCapturedLog;
+
+void LogCaptureFunction(Debug::DebugPriority priority, std::string& string)
+{
+ gCapturedLogPriority = priority;
+ gCapturedLog = string;
+}
+
+bool CheckCapturedLogContainString(Debug::DebugPriority priority, std::string string)
+{
+ bool ret = false;
+ if(gCapturedLogPriority == priority)
+ {
+ ret = (gCapturedLog.find(string) != std::string::npos);
+ }
+ return ret;
+}
+
+// Define static dummy filter, for line coverage.
+DALI_INIT_TIME_CHECKER_FILTER(gDummyTimeCheckerFilter, SOME_ENVORINMENT);
+} // namespace
+
+void utc_dali_internal_debug_startup()
+{
+ test_return_value = TET_UNDEF;
+
+ gCapturedLog.clear();
+}
+
+void utc_dali_internal_debug_cleanup()
+{
+ gCapturedLog.clear();
+
+ test_return_value = TET_PASS;
+}
+
+int UtcDaliDebugLogPrintP(void)
+{
+ TestApplication application;
+
+ tet_infoline("UtcDaliDebugLogPrintP() Test dali default log macros");
+
+ Debug::InstallLogFunction(LogCaptureFunction);
+
+ std::string expectLogString = "some expect logs";
+
+ DALI_LOG_ERROR("%s", expectLogString.c_str());
+ DALI_TEST_EQUALS(CheckCapturedLogContainString(Debug::DebugPriority::ERROR, expectLogString), true, TEST_LOCATION);
+
+ DALI_LOG_WARNING("%s", expectLogString.c_str());
+ DALI_TEST_EQUALS(CheckCapturedLogContainString(Debug::DebugPriority::WARNING, expectLogString), true, TEST_LOCATION);
+
+ DALI_LOG_RELEASE_INFO("%s", expectLogString.c_str());
+ DALI_TEST_EQUALS(CheckCapturedLogContainString(Debug::DebugPriority::INFO, expectLogString), true, TEST_LOCATION);
+
+ DALI_LOG_DEBUG_INFO("%s", expectLogString.c_str());
+ DALI_TEST_EQUALS(CheckCapturedLogContainString(Debug::DebugPriority::DEBUG, expectLogString), true, TEST_LOCATION);
+
+ Debug::UninstallLogFunction();
+
+ END_TEST;
+}
+
+int UtcDaliDebugTimeCheckerP(void)
+{
+ TestApplication application;
+
+ tet_infoline("UtcDaliDebugTimeCheckerP() Test time checker without environment");
+
+ Debug::InstallLogFunction(LogCaptureFunction);
+
+ auto* enabledFilter = Dali::Integration::TimeChecker::ThresholdFilter::New(0, "SOME_ENVORINMENT");
+ auto* disabledFilter = Dali::Integration::TimeChecker::ThresholdFilter::New(std::numeric_limits<uint32_t>::max(), "SOME_ENVORINMENT");
+
+ DALI_TEST_EQUALS(enabledFilter->IsEnabled(), true, TEST_LOCATION);
+ DALI_TEST_EQUALS(disabledFilter->IsEnabled(), false, TEST_LOCATION);
+ DALI_TEST_EQUALS(gDummyTimeCheckerFilter->IsEnabled(), false, TEST_LOCATION);
+
+ std::string expectLogString = "some expect logs";
+
+ tet_printf("Use function directly.\n");
+ tet_printf("Check enabled filter print log\n");
+ enabledFilter->BeginTimeCheck();
+ enabledFilter->EndTimeCheck(expectLogString.c_str(), "", "", 0);
+ DALI_TEST_EQUALS(CheckCapturedLogContainString(Debug::DebugPriority::INFO, expectLogString), true, TEST_LOCATION);
+
+ tet_printf("Check disabled filter don't print log\n");
+ // Clean up captured log first
+ gCapturedLog.clear();
+ disabledFilter->BeginTimeCheck();
+ disabledFilter->EndTimeCheck(expectLogString.c_str(), "", "", 0);
+ DALI_TEST_EQUALS(gCapturedLog.empty(), true, TEST_LOCATION);
+
+ tet_printf("Use function by macro.\n");
+ tet_printf("Check enabled filter print log\n");
+ DALI_TIME_CHECKER_BEGIN(enabledFilter);
+ DALI_TIME_CHECKER_BEGIN(enabledFilter);
+ DALI_TIME_CHECKER_BEGIN(enabledFilter);
+
+ DALI_TIME_CHECKER_END(enabledFilter);
+ DALI_TEST_EQUALS(CheckCapturedLogContainString(Debug::DebugPriority::INFO, "ms"), true, TEST_LOCATION);
+
+ DALI_TIME_CHECKER_END_WITH_MESSAGE(enabledFilter, "simple message");
+ DALI_TEST_EQUALS(CheckCapturedLogContainString(Debug::DebugPriority::INFO, "simple message"), true, TEST_LOCATION);
+
+ bool messageGeneratorExcuted = false;
+
+ DALI_TIME_CHECKER_END_WITH_MESSAGE_GENERATOR(enabledFilter, [&](std::ostringstream& oss) {
+ messageGeneratorExcuted = true;
+ oss << "complex message";
+ });
+ DALI_TEST_EQUALS(messageGeneratorExcuted, true, TEST_LOCATION);
+ DALI_TEST_EQUALS(CheckCapturedLogContainString(Debug::DebugPriority::INFO, "complex message"), true, TEST_LOCATION);
+
+ tet_printf("Check disabled filter don't print log\n");
+ // Clean up captured log first
+ gCapturedLog.clear();
+ DALI_TIME_CHECKER_BEGIN(gDummyTimeCheckerFilter);
+ DALI_TIME_CHECKER_BEGIN(gDummyTimeCheckerFilter);
+ DALI_TIME_CHECKER_BEGIN(gDummyTimeCheckerFilter);
+
+ DALI_TIME_CHECKER_END(gDummyTimeCheckerFilter);
+ DALI_TEST_EQUALS(gCapturedLog.empty(), true, TEST_LOCATION);
+
+ DALI_TIME_CHECKER_END_WITH_MESSAGE(gDummyTimeCheckerFilter, "simple message");
+ DALI_TEST_EQUALS(gCapturedLog.empty(), true, TEST_LOCATION);
+
+ messageGeneratorExcuted = false;
+ DALI_TIME_CHECKER_END_WITH_MESSAGE_GENERATOR(gDummyTimeCheckerFilter, [&](std::ostringstream& oss) {
+ messageGeneratorExcuted = true;
+ oss << "complex message";
+ });
+ DALI_TEST_EQUALS(messageGeneratorExcuted, false, TEST_LOCATION);
+ DALI_TEST_EQUALS(gCapturedLog.empty(), true, TEST_LOCATION);
+
+ Debug::UninstallLogFunction();
+
+ END_TEST;
+}
+
+int UtcDaliDebugTimeCheckerScopeTracerP(void)
+{
+ TestApplication application;
+
+ tet_infoline("UtcDaliDebugTimeCheckerScopeTracerP() Test time checker without environment");
+
+ Debug::InstallLogFunction(LogCaptureFunction);
+
+ auto* enabledFilter = Dali::Integration::TimeChecker::ThresholdFilter::New(0, "SOME_ENVORINMENT");
+
+ DALI_TEST_EQUALS(enabledFilter->IsEnabled(), true, TEST_LOCATION);
+
+ std::string expectLogString = "some expect logs";
+ {
+ DALI_TIME_CHECKER_SCOPE(enabledFilter, expectLogString.c_str());
+ DALI_TEST_EQUALS(gCapturedLog.empty(), true, TEST_LOCATION);
+ std::string expectLogString2 = "another expect logs";
+ {
+ DALI_TIME_CHECKER_SCOPE(enabledFilter, expectLogString2.c_str());
+ DALI_TEST_EQUALS(gCapturedLog.empty(), true, TEST_LOCATION);
+ }
+ DALI_TEST_EQUALS(CheckCapturedLogContainString(Debug::DebugPriority::INFO, expectLogString2), true, TEST_LOCATION);
+
+ // Clean up captured log first
+ gCapturedLog.clear();
+ {
+ DALI_TIME_CHECKER_SCOPE(enabledFilter, expectLogString2.c_str());
+ DALI_TEST_EQUALS(gCapturedLog.empty(), true, TEST_LOCATION);
+ }
+ DALI_TEST_EQUALS(CheckCapturedLogContainString(Debug::DebugPriority::INFO, expectLogString2), true, TEST_LOCATION);
+ }
+ DALI_TEST_EQUALS(CheckCapturedLogContainString(Debug::DebugPriority::INFO, expectLogString), true, TEST_LOCATION);
+
+ Debug::UninstallLogFunction();
+
+ END_TEST;
+}
#include <cstdarg>
#include <memory>
+// INTERNAL INCLUDES
+#include <dali/public-api/common/list-wrapper.h>
+#include <dali/public-api/common/vector-wrapper.h>
+
namespace Dali
{
#ifdef DEBUG_ENABLED
return s;
}
-#ifdef DEBUG_ENABLED
-
void GetNanoseconds(uint64_t& timeInNanoseconds)
{
// Get the time of a monotonic clock since its epoch.
timeInNanoseconds = static_cast<uint64_t>(duration.count());
}
-#endif // DEBUG_ENABLED
-
} // namespace Log
+namespace TimeChecker
+{
+typedef std::list<std::unique_ptr<ThresholdFilter>> FilterList;
+
+namespace
+{
+constexpr uint64_t MILLISECONDS_TO_NANOSECONDS = 1'000'000;
+
+static FilterList& GetActiveFilters()
+{
+ thread_local static FilterList activeFilters;
+ return activeFilters;
+}
+} // namespace
+
+struct ThresholdFilter::Impl
+{
+ std::vector<uint64_t> mTimeStamps;
+};
+
+ThresholdFilter* ThresholdFilter::New(ThresholdFilter::Milliseconds thresholdMilliSeconds, const char* environmentVariableName)
+{
+ try
+ {
+ char* environmentVariableValue = getenv(environmentVariableName);
+ if(environmentVariableValue)
+ {
+ thresholdMilliSeconds = static_cast<Milliseconds>(std::atoi(environmentVariableValue));
+ }
+ }
+ catch(...)
+ {
+ // Do nothing, just use default value.
+ }
+
+ ThresholdFilter* thresholdFilter = new ThresholdFilter(thresholdMilliSeconds);
+
+ GetActiveFilters().push_back(std::unique_ptr<ThresholdFilter>(thresholdFilter));
+ return thresholdFilter;
+}
+
+void ThresholdFilter::BeginTimeCheck()
+{
+ if(DALI_LIKELY(IsEnabled()))
+ {
+ uint64_t currentTime;
+ Log::GetNanoseconds(currentTime);
+ mImpl->mTimeStamps.push_back(currentTime);
+ }
+}
+
+void ThresholdFilter::EndTimeCheck(const char* messagePrefix, const char* module, const char* function, const int line)
+{
+ if(DALI_LIKELY(IsEnabled() && !mImpl->mTimeStamps.empty()))
+ {
+ uint64_t currentTime;
+ Log::GetNanoseconds(currentTime);
+
+ uint64_t duration = currentTime - mImpl->mTimeStamps.back();
+ mImpl->mTimeStamps.pop_back();
+
+ if(duration >= static_cast<uint64_t>(mThresholdMilliSeconds) * MILLISECONDS_TO_NANOSECONDS)
+ {
+ // Use LogMessage function directly, to print correct module / function and line.
+ Dali::Integration::Log::LogMessage(Dali::Integration::Log::INFO, DALI_LOG_FORMAT_PREFIX "%s takes [%.6lf ms]\n", module, function, line, messagePrefix ? messagePrefix : "", static_cast<double>(duration) / static_cast<double>(MILLISECONDS_TO_NANOSECONDS));
+ }
+ }
+}
+
+ThresholdFilter::ThresholdFilter(ThresholdFilter::Milliseconds thresholdMilliSeconds)
+: mThresholdMilliSeconds(thresholdMilliSeconds),
+ mImpl(new Impl())
+{
+}
+
+ScopeTracer::ScopeTracer(ThresholdFilter* filter, const char* messagePrefix, const char* module, const char* function, const int line)
+: mMessagePrefix(messagePrefix),
+ mModule(module),
+ mFunction(function),
+ mLine(line),
+ mFilter(filter)
+{
+ if(mFilter && mFilter->IsEnabled())
+ {
+ mFilter->BeginTimeCheck();
+ }
+}
+
+ScopeTracer::~ScopeTracer()
+{
+ if(mFilter && mFilter->IsEnabled())
+ {
+ mFilter->EndTimeCheck(mMessagePrefix, mModule, mFunction, mLine);
+ }
+}
+} // namespace TimeChecker
+
} // namespace Integration
} // namespace Dali
#include <stdint.h>
#include <cstring>
#include <iostream>
-#include <list>
+#include <memory>
#include <sstream>
#include <string>
+#include <dali/public-api/common/list-wrapper.h>
#include <dali/public-api/common/vector-wrapper.h>
#include <dali/public-api/object/property-map.h>
*
* @note The maximum value timeInNanoseconds can hold is 0xFFFFFFFFFFFFFFFF which is 1.844674407e+19. Therefore, this can overflow after approximately 584 years.
*/
-void GetNanoseconds(uint64_t& timeInNanoseconds);
+DALI_CORE_API void GetNanoseconds(uint64_t& timeInNanoseconds);
#define DALI_LOG_TIMER_START(timeVariable) \
uint64_t timeVariable##1; \
#endif
} // namespace Log
+
+namespace TimeChecker
+{
+/**
+ * @brief Print as release info if elapsed time greater or equal than threshold. (milliseconds)
+ * You can also set threshold by environment value.
+ *
+ * threshold = -1 (==std::numeric_limits<uint32_t>::max()) means always not print.
+ * threshold = 0 mean always print.
+ *
+ * To check duration, call BeginTimeCheck() and EndTimeCheck() pairwise.
+ * The filter print duration at EndTimeCheck() by DALI_LOG_RELEASE_INFO.
+ * We can call it recursively.
+ *
+ * @code
+ * auto* filter = ThresholdFilter::New(20u, "specific_environment_value");
+ *
+ * filter->BeginTimeCheck();
+ * for(;;)
+ * {
+ * filter->BeginTimeCheck();
+ * // Some codes
+ * filter->EndTimeCheck("Phase 1");
+ * filter->BeginTimeCheck();
+ * // Some codes
+ * filter->EndTimeCheck("Phase 2");
+ * }
+ * filter->EndTimeCheck("Total");
+ * @endcode
+ */
+class DALI_CORE_API ThresholdFilter
+{
+public:
+ using Milliseconds = uint32_t;
+
+ /**
+ * @brief Create new filter object.
+ * The ownership of memory hold in global static list.
+ * It will be released when thread joined.
+ * @return New allocated filter with threshold and environment.
+ */
+ static ThresholdFilter* New(ThresholdFilter::Milliseconds thresholdMilliSeconds, const char* environmentVariableName);
+
+ /**
+ * @brief Check whether this filter is enabled or not.
+ * @return True if threshold is valid value. False if threshold is -1 (==std::numeric_limits<uint32_t>::max())
+ */
+ inline bool IsEnabled()
+ {
+ return mThresholdMilliSeconds != std::numeric_limits<Milliseconds>::max();
+ }
+
+ /**
+ * @brief Begin time checker.
+ * @post EndTimeCheck() should be called after.
+ */
+ void BeginTimeCheck();
+
+ /**
+ * @brief End time checker.
+ * Print log if duration is greater of equal than threshold.
+ * @param[in] messagePrefix Prefix of message.
+ * @param[in] module The name of module who call this checker
+ * @param[in] fuction The name of function who call this checker
+ * @param[in] line The line number of function who call this checker.
+ * @pre BeginTimeCheck() should be called before.
+ */
+ void EndTimeCheck(const char* messagePrefix, const char* module, const char* function, const int line);
+
+private:
+ ThresholdFilter(Milliseconds thresholdMilliSeconds);
+
+private:
+ Milliseconds mThresholdMilliSeconds;
+
+ struct Impl;
+ std::unique_ptr<Impl> mImpl;
+};
+
+/**
+ * @brief The ScopeTracer object is used by the DALI_TIME_CHECKER_SCOPE macros.
+ */
+class DALI_CORE_API ScopeTracer final
+{
+public:
+ ScopeTracer(ThresholdFilter* filter, const char* messagePrefix, const char* module, const char* function, const int line);
+ ~ScopeTracer();
+
+public:
+ const char* mMessagePrefix;
+ const char* mModule;
+ const char* mFunction;
+ const int mLine;
+
+ ThresholdFilter* mFilter;
+};
+
+/**
+ * @brief Initialization of time checker filter
+ * Note that filter must be thread_local scoped
+ * @ref ThresholdFilter::New
+ */
+#define DALI_INIT_TIME_CHECKER_FILTER_WITH_DEFAULT_THRESHOLD(name, environmentVariableName, threshold) \
+ namespace \
+ { \
+ thread_local Dali::Integration::TimeChecker::ThresholdFilter* name = Dali::Integration::TimeChecker::ThresholdFilter::New(threshold, #environmentVariableName); \
+ }
+
+/**
+ * @brief Shorten filter macro without default threshold value.
+ * It will make filter disabled as default.
+ * @ref ThresholdFilter::New
+ */
+#define DALI_INIT_TIME_CHECKER_FILTER(name, environmentVariableName) \
+ DALI_INIT_TIME_CHECKER_FILTER_WITH_DEFAULT_THRESHOLD(name, environmentVariableName, std::numeric_limits<Dali::Integration::TimeChecker::ThresholdFilter::Milliseconds>::max())
+
+/**
+ * @brief Begin of time checker
+ * @ref ThresholdFilter::BeginTimeCheck
+ */
+#define DALI_TIME_CHECKER_BEGIN(filter) \
+ if(filter && filter->IsEnabled()) \
+ { \
+ filter->BeginTimeCheck(); \
+ }
+
+/**
+ * @brief End of time checker without any prefix message
+ * @ref ThresholdFilter::EndTimeCheck
+ */
+#define DALI_TIME_CHECKER_END(filter) \
+ if(filter && filter->IsEnabled()) \
+ { \
+ filter->EndTimeCheck("", \
+ DALI_LOG_FORMAT_PREFIX_ARGS); \
+ }
+
+/**
+ * @brief End of time checker with simple prefix message
+ * @ref ThresholdFilter::EndTimeCheck
+ */
+#define DALI_TIME_CHECKER_END_WITH_MESSAGE(filter, message) \
+ if(filter && filter->IsEnabled()) \
+ { \
+ filter->EndTimeCheck(message, \
+ DALI_LOG_FORMAT_PREFIX_ARGS); \
+ }
+
+/**
+ * @brief End of time checker with prefix message generator
+ * @ref ThresholdFilter::EndTimeCheck
+ */
+#define DALI_TIME_CHECKER_END_WITH_MESSAGE_GENERATOR(filter, messageGenerator) \
+ if(filter && filter->IsEnabled()) \
+ { \
+ std::ostringstream oss; \
+ messageGenerator(oss); \
+ filter->EndTimeCheck(oss.str().c_str(), \
+ DALI_LOG_FORMAT_PREFIX_ARGS); \
+ }
+
+/**
+ * @brief Used for scope time check. It check time around a scope.
+ */
+#define DALI_TIME_CHECKER_SCOPE(filter, message) \
+ Dali::Integration::TimeChecker::ScopeTracer timeCheckerScopeTracer(filter, message, DALI_LOG_FORMAT_PREFIX_ARGS);
+
+} // namespace TimeChecker
} // namespace Integration
} // namespace Dali
projects / platform / core / uifw / dali-core.git / commitdiff