comphelper: add a profiling API

Using the guard style ProfileZone aZone("foo").

Test macro:

Sub TimeLog
toolkit = createUnoService("com.sun.star.awt.Toolkit")
toolkit.startRecording()
toolkit.processEventsToIdle()
toolkit.stopRecording()
a = toolkit.getRecordingAndClear()
s = ""
For Each i in a
s = s + i + ", "
Next i
Print s
End Sub

Change-Id: Iceaf9143d0387c87e7936dc67eecbbf71ee8d74a
Reviewed-on: https://gerrit.libreoffice.org/38786Reviewed-by: Miklos Vajna <vmiklos@collabora.co.uk>
Reviewed-by: Noel Grandin <noel.grandin@collabora.co.uk>
Tested-by: Jenkins <ci@libreoffice.org>

comphelper/Library_comphelper.mk

@@ -117,6 +117,7 @@ $(eval $(call gb_Library_add_exception_objects,comphelper,\
     comphelper/source/misc/numbers \
     comphelper/source/misc/officeresourcebundle \
     comphelper/source/misc/officerestartmanager \
+    comphelper/source/misc/profilezone \
     comphelper/source/misc/proxyaggregation \
     comphelper/source/misc/random \
     comphelper/source/misc/scopeguard \

comphelper/source/misc/profilezone.cxx

+/* -*- 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 <comphelper/sequence.hxx>
+#include <comphelper/profilezone.hxx>
+#include <osl/time.h>
+#include <osl/thread.h>
+
+namespace comphelper
+{
+
+namespace ProfileRecording
+{
+
+static bool g_bRecording(false);              // true during recording
+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;
+
+void startRecording(bool bStartRecording)
+{
+    ::osl::MutexGuard aGuard( g_aMutex );
+    if (bStartRecording)
+    {
+        TimeValue systemTime;
+        osl_getSystemTime( &systemTime );
+        g_aStartTime = (long long) systemTime.Seconds * 1000000 + systemTime.Nanosec/1000;
+        g_aNesting = 0;
+    }
+    g_bRecording = bStartRecording;
+}
+
+long long addRecording(const char * aProfileId, long long aCreateTime)
+{
+    ::osl::MutexGuard aGuard( g_aMutex );
+    if ( g_bRecording )
+    {
+        TimeValue systemTime;
+        osl_getSystemTime( &systemTime );
+        long long aTime = (long long) systemTime.Seconds * 1000000 + systemTime.Nanosec/1000;
+        OUString aString(aProfileId, strlen(aProfileId), RTL_TEXTENCODING_UTF8);
+        g_aRecording.push_back(
+            OUString::number(osl_getThreadIdentifier(nullptr)) + " " +
+            OUString::number(aTime/1000000.0) + " " + aString + ": " +
+            (aCreateTime == 0 ? OUString("start") : OUString("stop"))
+        );
+        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;
+}
+
+css::uno::Sequence<OUString> getRecordingAndClear()
+{
+    bool bRecording;
+    std::vector<OUString> aRecording;
+    {
+        ::osl::MutexGuard aGuard( g_aMutex );
+        bRecording = g_bRecording;
+        startRecording(false);
+        aRecording.swap(g_aRecording);
+        long long aSumTime = g_aSumTime;
+        aRecording.insert(aRecording.begin(), OUString::number(aSumTime/1000000.0));
+    }
+    // reset start time and nesting level
+    startRecording(bRecording);
+    return ::comphelper::containerToSequence(aRecording);
+}
+
+} // namespace ProfileRecording
+
+
+ProfileZone::ProfileZone(const char * sProfileId) :
+    m_sProfileId(sProfileId)
+{
+    m_aCreateTime = ProfileRecording::addRecording(sProfileId, 0);
+}
+
+ProfileZone::~ProfileZone()
+{
+    ProfileRecording::addRecording(m_sProfileId, m_aCreateTime);
+}
+
+} // namespace comphelper
+
+/* vim:set shiftwidth=4 softtabstop=4 expandtab: */

include/comphelper/profilezone.hxx

+/* -*- Mode: C; tab-width: 4; indent-tabs-mode: nil; c-basic-offset: 4; fill-column: 100 -*- */
+/*
+ * 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/.
+*/
+
+#ifndef INCLUDED_COMPHELPER_PROFILEZONE_HXX
+#define INCLUDED_COMPHELPER_PROFILEZONE_HXX
+
+#include <com/sun/star/uno/Sequence.hxx>
+#include <comphelper/comphelperdllapi.h>
+#include <osl/mutex.hxx>
+#include <rtl/ustring.hxx>
+
+#include <vector>
+
+// implementation of XToolkitExperimental profiling API
+
+namespace comphelper
+{
+
+namespace ProfileRecording
+{
+
+COMPHELPER_DLLPUBLIC void startRecording(bool bRecording = true);
+
+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 m_aCreateTime;
+public:
+    ProfileZone(const char * sProfileId);
+    ~ProfileZone();
+};
+
+} // namespace comphelper
+
+
+#endif // INCLUDED_COMPHELPER_PROFILEZONE_HXX
+
+/* vim:set shiftwidth=4 softtabstop=4 expandtab: */

offapi/com/sun/star/awt/XToolkitExperimental.idl

@@ -34,6 +34,28 @@ interface XToolkitExperimental : XToolkit2
     /** Pause the main thread of LibreOffice for the requested amount of time.
      */
     void pause([in] long nMilliseconds);
+
+    /** Start time logging.
+
+        @since LibreOffice 6.0
+     */
+    void startRecording();
+
+    /** Stop time logging.
+
+        @since LibreOffice 6.0
+     */
+    void stopRecording();
+
+    /** Query time logs and clear recording.
+        First line is the time of the recorded operations in seconds,
+        next ones are the log lines. A log line contains the thread ID,
+        time stamp, profile zone ID and "start" or "stop".
+
+        @since LibreOffice 6.0
+     */
+    sequence<string> getRecordingAndClear();
+
 };
 
 }; }; }; };

toolkit/source/awt/vclxtoolkit.cxx

@@ -121,6 +121,7 @@
 #include <tools/debug.hxx>
 #include <comphelper/processfactory.hxx>
 #include <toolkit/awt/scrollabledialog.hxx>
+#include <comphelper/profilezone.hxx>
 
 #include "helper/unowrapper.hxx"
 
@@ -222,6 +223,12 @@ public:
 
     virtual void SAL_CALL pause(sal_Int32 nMilliseconds) override;
 
+    virtual void SAL_CALL startRecording() override;
+
+    virtual void SAL_CALL stopRecording() override;
+
+    css::uno::Sequence< OUString > SAL_CALL getRecordingAndClear() override;
+
     // css::awt::XToolkit
     css::uno::Reference< css::awt::XWindowPeer >  SAL_CALL getDesktopWindow(  ) override;
     css::awt::Rectangle                                        SAL_CALL getWorkArea(  ) override;
@@ -1887,6 +1894,7 @@ void SAL_CALL VCLXToolkit::reschedule()
 void SAL_CALL VCLXToolkit::processEventsToIdle()
 {
     SolarMutexGuard aSolarGuard;
+    ::comphelper::ProfileZone aZone("processEvents");
     Scheduler::ProcessEventsToIdle();
 }
 
@@ -1910,6 +1918,21 @@ void SAL_CALL VCLXToolkit::pause(sal_Int32 nMilliseconds)
     new Pause(nMilliseconds);
 }
 
+void SAL_CALL VCLXToolkit::startRecording()
+{
+    ::comphelper::ProfileRecording::startRecording();
+}
+
+void SAL_CALL VCLXToolkit::stopRecording()
+{
+    ::comphelper::ProfileRecording::startRecording( false );
+}
+
+css::uno::Sequence< OUString > VCLXToolkit::getRecordingAndClear()
+{
+    return ::comphelper::ProfileRecording::getRecordingAndClear();
+}
+
 // css:awt:XToolkitRobot
 
 void SAL_CALL VCLXToolkit::keyPress( const css::awt::KeyEvent & aKeyEvent )