Refactor ProfileZone and create Chrome Trace Event Format data

Instead of separate B ("begin") and E ("end") duration events,
generate X ("complete") events.

Only the event JSON objects are generated, not the surrounding array
or object.

See
https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/preview#heading=h.lc5airzennvk

Online now needs work so that the events are written out to a separate
file instead of being in the common log file.

Change-Id: Ie9363b4cfda862a70e1928ed16350e50a6fee9a5
Reviewed-on: https://gerrit.libreoffice.org/c/core/+/114142
Tested-by: Tor Lillqvist <tml@collabora.com>
Reviewed-by: Michael Meeks <michael.meeks@collabora.com>

4 files changed, 83 insertions, 80 deletions

diff --git a/comphelper/source/misc/profilezone.cxx b/comphelper/source/misc/profilezone.cxx
index 4d6d94744c88..dcca53e211eb 100644
--- a/comphelper/source/misc/profilezone.cxx
+++ b/comphelper/source/misc/profilezone.cxx
@@ -19,79 +19,68 @@
 namespace comphelper
 {
 
-std::atomic<bool> ProfileZone::g_bRecording(false);
+std::atomic<bool> ProfileZone::s_bRecording = false;
 
-namespace ProfileRecording
-{
-
-static std::vector<OUString> g_aRecording;    // recorded data
-static long long g_aSumTime(0);  // overall zone time in microsec
-static int g_aNesting;           // level of overlapped zones
-static long long g_aStartTime;                // start time of recording
-static ::osl::Mutex g_aMutex;
+int ProfileZone::s_nNesting = 0; // level of overlapped zones
 
-void startRecording()
+namespace
 {
-    TimeValue systemTime;
-    osl_getSystemTime( &systemTime );
-    ::osl::MutexGuard aGuard( g_aMutex );
-    g_aStartTime = static_cast<long long>(systemTime.Seconds) * 1000000 + systemTime.Nanosec/1000;
-    g_aNesting = 0;
-    ProfileZone::g_bRecording = true;
+    std::vector<OUString> g_aRecording; // recorded data
+    long long g_nSumTime(0);  // overall zone time in microsec
+    long long g_nStartTime;   // start time of recording
+    ::osl::Mutex g_aMutex;
 }
 
-void stopRecording()
+void ProfileZone::startRecording()
 {
-    ProfileZone::g_bRecording = false;
+    TimeValue aSystemTime;
+    osl_getSystemTime(&aSystemTime );
+    ::osl::MutexGuard aGuard(g_aMutex);
+    g_nStartTime = static_cast<long long>(aSystemTime.Seconds) * 1000000 + aSystemTime.Nanosec/1000;
+    s_nNesting = 0;
+    s_bRecording = true;
 }
 
-long long addRecording(const char * aProfileId, long long aCreateTime)
+void ProfileZone::stopRecording()
 {
-    assert( ProfileZone::g_bRecording );
-
-    TimeValue systemTime;
-    osl_getSystemTime( &systemTime );
-    long long aTime = static_cast<long long>(systemTime.Seconds) * 1000000 + systemTime.Nanosec/1000;
-
-    if (!aProfileId)
-        aProfileId = "(null)";
-    OUString aString(aProfileId, strlen(aProfileId), RTL_TEXTENCODING_UTF8);
-
-    OUString sRecordingData(OUString::number(osl_getThreadIdentifier(nullptr)) + " " +
-        OUString::number(aTime/1000000.0) + " " + aString + ": " +
-        (aCreateTime == 0 ? OUStringLiteral("start") : OUStringLiteral("stop")) +
-        (aCreateTime != 0 ? (" " + OUString::number((aTime - aCreateTime)/1000.0) + " ms") : OUString("")));
+    s_bRecording = false;
+}
 
-    ::osl::MutexGuard aGuard( g_aMutex );
+void ProfileZone::addRecording()
+{
+    assert(s_bRecording);
+
+    TimeValue aSystemTime;
+    osl_getSystemTime(&aSystemTime);
+    long long nNow = static_cast<long long>(aSystemTime.Seconds) * 1000000 + aSystemTime.Nanosec/1000;
+
+     // Generate a single "Complete Event" (type X)
+    OUString sRecordingData("{"
+                            "\"name\":\"" + OUString(m_sProfileId, strlen(m_sProfileId), RTL_TEXTENCODING_UTF8) + "\","
+                            "\"ph\":\"X\","
+                            "\"ts\":" + OUString::number(m_nCreateTime) + ","
+                            "\"dur\":" + OUString::number(nNow - m_nCreateTime) + ","
+                            "\"pid\":" + OUString::number(m_nPid) + ","
+                            "\"tid\":" + OUString::number(osl_getThreadIdentifier(nullptr)) +
+                            "}");
+    ::osl::MutexGuard aGuard(g_aMutex);
 
     g_aRecording.emplace_back(sRecordingData);
-    if (aCreateTime == 0)
-    {
-        g_aNesting++;
-        return aTime;
-    }
-    // neglect ProfileZones created before startRecording
-    else if (aCreateTime >= g_aStartTime)
-    {
-        if (g_aNesting > 0)
-            g_aNesting--;
-        if (g_aNesting == 0)
-            g_aSumTime += aTime - aCreateTime;
-    }
-    return 0;
+    if (s_nNesting == 0)
+        g_nSumTime += nNow - m_nCreateTime;
 }
 
-css::uno::Sequence<OUString> getRecordingAndClear()
+css::uno::Sequence<OUString> ProfileZone::getRecordingAndClear()
 {
     bool bRecording;
     std::vector<OUString> aRecording;
     {
         ::osl::MutexGuard aGuard( g_aMutex );
-        bRecording = ProfileZone::g_bRecording;
+        bRecording = s_bRecording;
         stopRecording();
         aRecording.swap(g_aRecording);
-        long long aSumTime = g_aSumTime;
-        aRecording.insert(aRecording.begin(), OUString::number(aSumTime/1000000.0));
+        long long nSumTime = g_nSumTime;
+        aRecording.insert(aRecording.begin(), OUString::number(nSumTime/1000000.0));
     }
     // reset start time and nesting level
     if (bRecording)
@@ -99,9 +88,6 @@ css::uno::Sequence<OUString> getRecordingAndClear()
     return ::comphelper::containerToSequence(aRecording);
 }
 
-} // namespace ProfileRecording
-
-
 } // namespace comphelper
 
 /* vim:set shiftwidth=4 softtabstop=4 expandtab: */
diff --git a/desktop/source/lib/init.cxx b/desktop/source/lib/init.cxx
index c175b2fa02ad..7b8c9a47efab 100644
--- a/desktop/source/lib/init.cxx
+++ b/desktop/source/lib/init.cxx
@@ -6099,7 +6099,7 @@ public:
     virtual void Invoke() override
     {
         const css::uno::Sequence<OUString> aEvents =
-            comphelper::ProfileRecording::getRecordingAndClear();
+            comphelper::ProfileZone::getRecordingAndClear();
         OStringBuffer aOutput;
         for (const auto &s : aEvents)
         {
@@ -6179,7 +6179,7 @@ static int lo_initialize(LibreOfficeKit* pThis, const char* pAppPath, const char
     // Turn profile zones on early
     if (bProfileZones && eStage == SECOND_INIT)
     {
-        comphelper::ProfileRecording::startRecording();
+        comphelper::ProfileZone::startRecording();
         new ProfileZoneDumper();
     }
 
diff --git a/include/comphelper/profilezone.hxx b/include/comphelper/profilezone.hxx
index b54d69523fd6..3f758d88d987 100644
--- a/include/comphelper/profilezone.hxx
+++ b/include/comphelper/profilezone.hxx
@@ -14,6 +14,8 @@
 
 #include <atomic>
 
+#include <osl/process.h>
+#include <osl/time.h>
 #include <com/sun/star/uno/Sequence.h>
 #include <comphelper/comphelperdllapi.h>
 #include <rtl/ustring.hxx>
@@ -23,39 +25,54 @@
 namespace comphelper
 {
 
-namespace ProfileRecording
-{
-
-COMPHELPER_DLLPUBLIC void startRecording();
-COMPHELPER_DLLPUBLIC void stopRecording();
-
-COMPHELPER_DLLPUBLIC long long addRecording(const char * aProfileId, long long aCreateTime);
-
-COMPHELPER_DLLPUBLIC css::uno::Sequence<OUString> getRecordingAndClear();
-
-} // namespace ProfileRecording
-
 class COMPHELPER_DLLPUBLIC ProfileZone
 {
 private:
-    const char * m_sProfileId;
-    long long const m_aCreateTime;
-public:
-    static std::atomic<bool> g_bRecording; // true during recording
+    static std::atomic<bool> s_bRecording; // true during recording
+    static int s_nNesting;
+    const char *m_sProfileId;
+    long long m_nCreateTime;
+    int m_nPid;
+
+    void addRecording();
+
+ public:
 
     // Note that the char pointer is stored as such in the ProfileZone object and used in the
     // destructor, so be sure to pass a pointer that stays valid for the duration of the object's
     // lifetime.
     ProfileZone(const char *sProfileId)
-        : m_sProfileId(sProfileId),
-          m_aCreateTime(g_bRecording ? ProfileRecording::addRecording(sProfileId, 0) : 0)
+        : m_sProfileId(sProfileId ? sProfileId : "(null)")
     {
+        if (s_bRecording)
+        {
+            TimeValue systemTime;
+            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;
+
+            s_nNesting++;
+        }
+        else
+            m_nCreateTime = 0;
     }
     ~ProfileZone()
     {
-        if (g_bRecording)
-            ProfileRecording::addRecording(m_sProfileId, m_aCreateTime);
+        if (s_bRecording)
+        {
+            s_nNesting--;
+            addRecording();
+        }
     }
+
+    static void startRecording();
+    static void stopRecording();
+
+    static css::uno::Sequence<OUString> getRecordingAndClear();
 };
 
 } // namespace comphelper
diff --git a/toolkit/source/awt/vclxtoolkit.cxx b/toolkit/source/awt/vclxtoolkit.cxx
index 95e731beb2df..129cf5ee7300 100644
--- a/toolkit/source/awt/vclxtoolkit.cxx
+++ b/toolkit/source/awt/vclxtoolkit.cxx
@@ -2535,17 +2535,17 @@ void SAL_CALL VCLXToolkit::pause(sal_Int32 nMilliseconds)
 
 void SAL_CALL VCLXToolkit::startRecording()
 {
-    ::comphelper::ProfileRecording::startRecording();
+    comphelper::ProfileZone::startRecording();
 }
 
 void SAL_CALL VCLXToolkit::stopRecording()
 {
-    ::comphelper::ProfileRecording::stopRecording();
+    comphelper::ProfileZone::stopRecording();
 }
 
 css::uno::Sequence< OUString > VCLXToolkit::getRecordingAndClear()
 {
-    return ::comphelper::ProfileRecording::getRecordingAndClear();
+    return comphelper::ProfileZone::getRecordingAndClear();
 }
 
 // css:awt:XToolkitRobot