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(-)
New commits:
commit 0ca29b80530887d41e9c98e4bcf410efe4042d3e
Author: Tor Lillqvist <t...@collabora.com>
AuthorDate: Tue Apr 27 18:43:16 2021 +0300
Commit: Tor Lillqvist <t...@collabora.com>
CommitDate: Thu Apr 29 14:16:12 2021 +0200
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 <jenkinscollaboraoff...@gmail.com>
Reviewed-by: Tor Lillqvist <t...@collabora.com>
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 <sal/config.h>
+
+#include <comphelper/profilezone.hxx>
+#include <comphelper/traceevent.hxx>
+
+#include <rtl/ustring.hxx>
+
+#include <cppunit/TestFixture.h>
+#include <cppunit/extensions/HelperMacros.h>
+
+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<comphelper::AsyncEvent>("async 1"));
+
+ std::weak_ptr<comphelper::AsyncEvent> 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<comphelper::AsyncEvent> 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<comphelper::AsyncEvent>("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<comphelper::AsyncEvent>("async 3"));
+
+ std::weak_ptr<comphelper::AsyncEvent> 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 <comphelper/sequence.hxx>
#include <comphelper/traceevent.hxx>
-#include <osl/time.h>
-#include <osl/thread.h>
-
namespace comphelper
{
#ifdef DBG_UTIL
@@ -27,27 +24,25 @@ std::atomic<bool> TraceEvent::s_bRecording =
(getenv("TRACE_EVENT_RECORDING") !=
#else
std::atomic<bool> TraceEvent::s_bRecording = false;
#endif
+int AsyncEvent::s_nIdCounter = 0;
int ProfileZone::s_nNesting = 0;
namespace
{
std::vector<OUString> 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<long long>(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<OUString> TraceEvent::getRecordingAndClear()
+std::vector<OUString> TraceEvent::getEventVectorAndClear()
{
bool bRecording;
std::vector<OUString> 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<OUString>
TraceEvent::getRecordingAndClear()
// reset start time and nesting level
if (bRecording)
startRecording();
- return ::comphelper::containerToSequence(aRecording);
+ return aRecording;
+}
+
+css::uno::Sequence<OUString> TraceEvent::getRecordingAndClear()
+{
+ return comphelper::containerToSequence(getEventVectorAndClear());
}
void ProfileZone::addRecording()
{
assert(s_bRecording);
- TimeValue aSystemTime;
- osl_getSystemTime(&aSystemTime);
- long long nNow
- = static_cast<long long>(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<long long>(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 <atomic>
#include <memory>
-#include <set>
+#include <vector>
#include <osl/process.h>
+#include <osl/thread.h>
#include <osl/time.h>
#include <com/sun/star/uno/Sequence.h>
#include <comphelper/comphelperdllapi.h>
@@ -33,12 +34,31 @@ protected:
static void addRecording(const OUString& sObject);
+ static long long getNow()
+ {
+ TimeValue systemTime;
+ osl_getSystemTime(&systemTime);
+ return static_cast<long long>(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<OUString> getEventVectorAndClear();
+
static css::uno::Sequence<OUString> 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<AsyncEvent>
+{
+ static int s_nIdCounter;
+ int m_nId;
+ int m_nPid;
+ std::vector<std::shared_ptr<AsyncEvent>> 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<AsyncEvent> createWithParent(const char* sName,
+
std::shared_ptr<AsyncEvent> pParent)
+ {
+ std::shared_ptr<AsyncEvent> 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
_______________________________________________
Libreoffice-commits mailing list
libreoffice-comm...@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/libreoffice-commits
