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/+/114756
Tested-by: Jenkins
Reviewed-by: Tor Lillqvist <tml@collabora.com>

3 files changed, 136 insertions, 17 deletions

diff --git a/comphelper/CppunitTest_comphelper_test.mk b/comphelper/CppunitTest_comphelper_test.mk
index ef795f1664d1..de4ee90818f2 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 9febf71e2db7..81039c9ca82d 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("{"