From 0ca29b80530887d41e9c98e4bcf410efe4042d3e Mon Sep 17 00:00:00 2001 From: Tor Lillqvist Date: Tue, 27 Apr 2021 18:43:16 +0300 Subject: Introduce Async trace events and a unit test Async events are ones that emit separate 'b' (begin) and 'e' (end) traces. (Compare to the Complete event that emit a single 'X' trace that contains both the start timstamp and the duration.) There are two kinds of Async events: Freestanding ones that are not related to other events at all, and nested ones that have to be nested between the 'b' and 'e' events of a parent Async event. Still needs some work, at least a way to end a nested AsyncEvent (cause it to emit the 'e' event) before it gets destructed thanks to the parent being destructed. Change-Id: I3721fa701ad32639b1edc1cfa8db7acde5caf9b4 Reviewed-on: https://gerrit.libreoffice.org/c/core/+/114784 Tested-by: Jenkins CollaboraOffice Reviewed-by: Tor Lillqvist --- comphelper/CppunitTest_comphelper_test.mk | 1 + comphelper/qa/unit/test_traceevent.cxx | 121 ++++++++++++++++++++++++++++++ comphelper/source/misc/traceevent.cxx | 31 ++++---- include/comphelper/profilezone.hxx | 5 +- include/comphelper/traceevent.hxx | 115 +++++++++++++++++++++++++++- 5 files changed, 251 insertions(+), 22 deletions(-) create mode 100644 comphelper/qa/unit/test_traceevent.cxx diff --git a/comphelper/CppunitTest_comphelper_test.mk b/comphelper/CppunitTest_comphelper_test.mk index 8bb335aa24dc..39a08fbd17cb 100644 --- a/comphelper/CppunitTest_comphelper_test.mk +++ b/comphelper/CppunitTest_comphelper_test.mk @@ -16,6 +16,7 @@ $(eval $(call gb_CppunitTest_add_exception_objects,comphelper_test, \ comphelper/qa/unit/base64_test \ comphelper/qa/unit/types_test \ comphelper/qa/unit/test_guards \ + comphelper/qa/unit/test_traceevent \ )) $(eval $(call gb_CppunitTest_use_sdk_api,comphelper_test)) diff --git a/comphelper/qa/unit/test_traceevent.cxx b/comphelper/qa/unit/test_traceevent.cxx new file mode 100644 index 000000000000..e7e97b2032a5 --- /dev/null +++ b/comphelper/qa/unit/test_traceevent.cxx @@ -0,0 +1,121 @@ +/* -*- Mode: C++; tab-width: 4; indent-tabs-mode: nil; c-basic-offset: 4 -*- */ +/* + * This file is part of the LibreOffice project. + * + * This Source Code Form is subject to the terms of the Mozilla Public + * License, v. 2.0. If a copy of the MPL was not distributed with this + * file, You can obtain one at http://mozilla.org/MPL/2.0/. + */ + +#include + +#include +#include + +#include + +#include +#include + +class TestTraceEvent : public CppUnit::TestFixture +{ +public: + void test(); + + CPPUNIT_TEST_SUITE(TestTraceEvent); + CPPUNIT_TEST(test); + CPPUNIT_TEST_SUITE_END(); +}; + +namespace +{ +void trace_event_test() +{ + // When we start recording is off and this will not generate any 'X' event + comphelper::ProfileZone aZone0("test().0"); + + // This will not generate any 'b' and 'e' events either + auto pAsync1(std::make_shared("async 1")); + + std::weak_ptr pAsync2; + { + // No 'X' by this either + comphelper::ProfileZone aZone1("block 1"); + + // Now we turn on recording + comphelper::TraceEvent::startRecording(); + + // As this is nested in the parent that was created with recording turned off, + // this will not generate any 'b' and 'e' events either + pAsync2 = comphelper::AsyncEvent::createWithParent("async 2", pAsync1); + } + + // This will generate an 'i' event + comphelper::TraceEvent::addInstantEvent("instant 1"); + + std::shared_ptr pAsync25; + { + comphelper::ProfileZone aZone2("block 2"); + + // This does not generate any 'e' event as it was created when recording was off + // And the nested "async 2" object will thus not generate anything either + pAsync1.reset(); + + // This will generate 'b' event and an 'e' event when the pointer is reset or goes out of scope + pAsync25 = std::make_shared("async 2.5"); + + // Leaving this scope will generate an 'X' event for "block 2" + } + + // Verify that the weak_ptr to pAsync2 has expired as its parent pAsync1 has been finished off + CPPUNIT_ASSERT(pAsync2.expired()); + + // This will generate a 'b' event + auto pAsync3(std::make_shared("async 3")); + + std::weak_ptr pAsync4; + { + comphelper::ProfileZone aZone3("block 3"); + + pAsync4 = comphelper::AsyncEvent::createWithParent("async 4", pAsync3); + + // Leaving this scope will generate an 'X' event for "block 3" + } + + // This will generate an 'e' event for "async 2.5" + pAsync25.reset(); + + comphelper::ProfileZone aZone4("test().2"); + + // This will generate an 'i' event + comphelper::TraceEvent::addInstantEvent("instant 2"); + + // Leaving this scope will generate 'X' events for "test().2" and a 'e' event for pAsync4 and pAsync3 +} +} + +void TestTraceEvent::test() +{ + trace_event_test(); + auto aEvents = comphelper::TraceEvent::getEventVectorAndClear(); + for (const auto& s : aEvents) + { + std::cerr << s << "\n"; + } + + CPPUNIT_ASSERT(aEvents[0].startsWith("{\"name:\"instant 1\",\"ph\":\"i\",")); + CPPUNIT_ASSERT(aEvents[1].startsWith("{\"name\":\"async 2.5\",\"ph\":\"b\",\"id\":1\",")); + CPPUNIT_ASSERT(aEvents[2].startsWith("{\"name\":\"block 2\",\"ph\":\"X\",")); + CPPUNIT_ASSERT(aEvents[3].startsWith("{\"name\":\"async 3\",\"ph\":\"b\",\"id\":2\",")); + CPPUNIT_ASSERT(aEvents[4].startsWith("{\"name\":\"async 4\",\"ph\":\"b\",\"id\":2\",")); + CPPUNIT_ASSERT(aEvents[5].startsWith("{\"name\":\"block 3\",\"ph\":\"X\",")); + CPPUNIT_ASSERT(aEvents[6].startsWith("{\"name\":\"async 2.5\",\"ph\":\"e\",\"id\":1\",")); + CPPUNIT_ASSERT(aEvents[7].startsWith("{\"name:\"instant 2\",\"ph\":\"i\",")); + CPPUNIT_ASSERT(aEvents[8].startsWith("{\"name\":\"test().2\",\"ph\":\"X\"")); + CPPUNIT_ASSERT(aEvents[9].startsWith("{\"name\":\"async 4\",\"ph\":\"e\",\"id\":2\",")); + CPPUNIT_ASSERT(aEvents[10].startsWith("{\"name\":\"async 3\",\"ph\":\"e\",\"id\":2\",")); +} + +CPPUNIT_TEST_SUITE_REGISTRATION(TestTraceEvent); + +/* vim:set shiftwidth=4 softtabstop=4 expandtab: */ diff --git a/comphelper/source/misc/traceevent.cxx b/comphelper/source/misc/traceevent.cxx index bd8a336d37ea..a352f9cc6a8a 100644 --- a/comphelper/source/misc/traceevent.cxx +++ b/comphelper/source/misc/traceevent.cxx @@ -17,9 +17,6 @@ #include #include -#include -#include - namespace comphelper { #ifdef DBG_UTIL @@ -27,27 +24,25 @@ std::atomic TraceEvent::s_bRecording = (getenv("TRACE_EVENT_RECORDING") != #else std::atomic TraceEvent::s_bRecording = false; #endif +int AsyncEvent::s_nIdCounter = 0; int ProfileZone::s_nNesting = 0; namespace { std::vector g_aRecording; // recorded data -::osl::Mutex g_aMutex; +osl::Mutex g_aMutex; } void TraceEvent::addRecording(const OUString& sObject) { - ::osl::MutexGuard aGuard(g_aMutex); + osl::MutexGuard aGuard(g_aMutex); g_aRecording.emplace_back(sObject); } void TraceEvent::addInstantEvent(const char* sName) { - TimeValue aSystemTime; - osl_getSystemTime(&aSystemTime); - long long nNow - = static_cast(aSystemTime.Seconds) * 1000000 + aSystemTime.Nanosec / 1000; + long long nNow = getNow(); int nPid = 0; oslProcessInfo aProcessInfo; @@ -72,18 +67,18 @@ void TraceEvent::addInstantEvent(const char* sName) void TraceEvent::startRecording() { - ::osl::MutexGuard aGuard(g_aMutex); + osl::MutexGuard aGuard(g_aMutex); s_bRecording = true; } void TraceEvent::stopRecording() { s_bRecording = false; } -css::uno::Sequence TraceEvent::getRecordingAndClear() +std::vector TraceEvent::getEventVectorAndClear() { bool bRecording; std::vector aRecording; { - ::osl::MutexGuard aGuard(g_aMutex); + osl::MutexGuard aGuard(g_aMutex); bRecording = s_bRecording; stopRecording(); aRecording.swap(g_aRecording); @@ -91,17 +86,19 @@ css::uno::Sequence TraceEvent::getRecordingAndClear() // reset start time and nesting level if (bRecording) startRecording(); - return ::comphelper::containerToSequence(aRecording); + return aRecording; +} + +css::uno::Sequence TraceEvent::getRecordingAndClear() +{ + return comphelper::containerToSequence(getEventVectorAndClear()); } void ProfileZone::addRecording() { assert(s_bRecording); - TimeValue aSystemTime; - osl_getSystemTime(&aSystemTime); - long long nNow - = static_cast(aSystemTime.Seconds) * 1000000 + aSystemTime.Nanosec / 1000; + long long nNow = getNow(); // Generate a single "Complete Event" (type X) TraceEvent::addRecording("{" diff --git a/include/comphelper/profilezone.hxx b/include/comphelper/profilezone.hxx index 2e0777295aa6..e8b2ce99472b 100644 --- a/include/comphelper/profilezone.hxx +++ b/include/comphelper/profilezone.hxx @@ -43,10 +43,7 @@ class COMPHELPER_DLLPUBLIC ProfileZone : public NamedEvent osl_getSystemTime( &systemTime ); m_nCreateTime = static_cast(systemTime.Seconds) * 1000000 + systemTime.Nanosec/1000; - oslProcessInfo aProcessInfo; - aProcessInfo.Size = sizeof(oslProcessInfo); - if (osl_getProcessInfo(nullptr, osl_Process_IDENTIFIER, &aProcessInfo) == osl_Process_E_None) - m_nPid = aProcessInfo.Ident; + m_nPid = getPid(); m_nNesting = s_nNesting++; } diff --git a/include/comphelper/traceevent.hxx b/include/comphelper/traceevent.hxx index 7e988bd063f0..3d3c748ec278 100644 --- a/include/comphelper/traceevent.hxx +++ b/include/comphelper/traceevent.hxx @@ -14,9 +14,10 @@ #include #include -#include +#include #include +#include #include #include #include @@ -33,12 +34,31 @@ protected: static void addRecording(const OUString& sObject); + static long long getNow() + { + TimeValue systemTime; + osl_getSystemTime(&systemTime); + return static_cast(systemTime.Seconds) * 1000000 + systemTime.Nanosec / 1000; + } + + static int getPid() + { + oslProcessInfo aProcessInfo; + aProcessInfo.Size = sizeof(oslProcessInfo); + if (osl_getProcessInfo(nullptr, osl_Process_IDENTIFIER, &aProcessInfo) + == osl_Process_E_None) + return aProcessInfo.Ident; + return -1; + } + public: static void addInstantEvent(const char* sName); static void startRecording(); static void stopRecording(); + static std::vector getEventVectorAndClear(); + static css::uno::Sequence getRecordingAndClear(); }; @@ -53,6 +73,99 @@ protected: } }; +// An AsyncEvent generates a 'b' (begin) event when constructed and an 'e' (end) event when destructed + +class COMPHELPER_DLLPUBLIC AsyncEvent : public NamedEvent, + public std::enable_shared_from_this +{ + static int s_nIdCounter; + int m_nId; + int m_nPid; + std::vector> m_aChildren; + bool m_bBeginRecorded; + + AsyncEvent(const char* sName, int nId) + : NamedEvent(sName) + , m_nId(nId) + , m_bBeginRecorded(false) + { + if (s_bRecording) + { + long long nNow = getNow(); + + m_nPid = getPid(); + + // Generate a "Begin " (type b) event + TraceEvent::addRecording("{" + "\"name\":\"" + + OUString(m_sName, strlen(m_sName), RTL_TEXTENCODING_UTF8) + + "\"," + "\"ph\":\"b\"" + "," + "\"id\":" + + OUString::number(m_nId) + + "\"," + "\"ts\":" + + OUString::number(nNow) + + "," + "\"pid\":" + + OUString::number(m_nPid) + + "," + "\"tid\":" + + OUString::number(osl_getThreadIdentifier(nullptr)) + "},"); + m_bBeginRecorded = true; + } + } + +public: + AsyncEvent(const char* sName) + : AsyncEvent(sName, s_nIdCounter++) + { + } + + ~AsyncEvent() + { + if (m_bBeginRecorded) + { + m_aChildren.clear(); + + long long nNow = getNow(); + // Generate a "Env " (type e) event + TraceEvent::addRecording("{" + "\"name\":\"" + + OUString(m_sName, strlen(m_sName), RTL_TEXTENCODING_UTF8) + + "\"," + "\"ph\":\"e\"" + "," + "\"id\":" + + OUString::number(m_nId) + + "\"," + "\"ts\":" + + OUString::number(nNow) + + "," + "\"pid\":" + + OUString::number(m_nPid) + + "," + "\"tid\":" + + OUString::number(osl_getThreadIdentifier(nullptr)) + "},"); + } + } + + static std::weak_ptr createWithParent(const char* sName, + std::shared_ptr pParent) + { + std::shared_ptr pResult; + + if (s_bRecording && pParent->m_bBeginRecorded) + { + pResult.reset(new AsyncEvent(sName, pParent->m_nId)); + pParent->m_aChildren.push_back(pResult); + } + + return pResult; + } +}; + } // namespace comphelper #endif // INCLUDED_COMPHELPER_TRACEEVENT_HXX -- cgit