Add PerfLog (#3974)

Add `PerfTime` class representing a point in CPU time and `PerfLogTimer`, used for measuring and logging a time period. Used in `ProjectRenderer::run()

CMakeLists.txt

@@ -124,6 +124,7 @@ CHECK_INCLUDE_FILES(sys/types.h LMMS_HAVE_SYS_TYPES_H)
 CHECK_INCLUDE_FILES(sys/ipc.h LMMS_HAVE_SYS_IPC_H)
 CHECK_INCLUDE_FILES(sys/shm.h LMMS_HAVE_SYS_SHM_H)
 CHECK_INCLUDE_FILES(sys/time.h LMMS_HAVE_SYS_TIME_H)
+CHECK_INCLUDE_FILES(sys/times.h LMMS_HAVE_SYS_TIMES_H)
 CHECK_INCLUDE_FILES(sched.h LMMS_HAVE_SCHED_H)
 CHECK_INCLUDE_FILES(sys/soundcard.h LMMS_HAVE_SYS_SOUNDCARD_H)
 CHECK_INCLUDE_FILES(soundcard.h LMMS_HAVE_SOUNDCARD_H)
@@ -250,7 +251,7 @@ IF(WANT_SDL AND NOT LMMS_HAVE_SDL2)
 		IF(NOT SDL_INCLUDE_DIR)
 			SET(SDL_INCLUDE_DIR "${CMAKE_FIND_ROOT_PATH}/include")
 		ENDIF()
-		
+
 	ELSE()
 		SET(STATUS_SDL "not found, please install libsdl2-dev (or similar) "
 			"if you require SDL support")

include/PerfLog.h

@@ -0,0 +1,73 @@
+/*
+ * PerfLog.h - Small performance logger
+ *
+ * Copyright (c) 2017-2018 LMMS Developers
+ *
+ * This file is part of LMMS - https://lmms.io
+ *
+ * This program is free software; you can redistribute it and/or
+ * modify it under the terms of the GNU General Public
+ * License as published by the Free Software Foundation; either
+ * version 2 of the License, or (at your option) any later version.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
+ * General Public License for more details.
+ *
+ * You should have received a copy of the GNU General Public
+ * License along with this program (see COPYING); if not, write to the
+ * Free Software Foundation, Inc., 51 Franklin Street, Fifth Floor,
+ * Boston, MA 02110-1301 USA.
+ *
+ */
+
+#ifndef PERFLOG_H
+#define PERFLOG_H
+
+#include <ctime>
+#include <QtCore/QString>
+
+/// \brief CPU time point
+///
+/// Represents a point in CPU time (not wall-clock time) intended for measuring
+/// performance.
+class PerfTime
+{
+public:
+	PerfTime();
+	bool valid() const;
+
+	clock_t real() const;
+	clock_t user() const;
+	clock_t system() const;
+
+	static PerfTime now();
+	static clock_t ticksPerSecond();
+
+	friend PerfTime operator-(const PerfTime& lhs, const PerfTime& rhs);
+private:
+	clock_t m_real;
+	clock_t m_user;
+	clock_t m_system;
+};
+
+/// \brief The PerfLog class
+///
+/// Measures time between construction and destruction and prints the result to
+/// stderr, along with \p name. Alternatively, call begin() and end() explicitly.
+class PerfLogTimer
+{
+ public:
+	PerfLogTimer(const QString& name);
+	~PerfLogTimer();
+
+	void begin();
+	void end();
+
+ private:
+	QString name;
+	PerfTime begin_time;
+};
+
+#endif

src/core/CMakeLists.txt

@@ -44,6 +44,7 @@ set(LMMS_SRCS
 	core/NotePlayHandle.cpp
 	core/Oscillator.cpp
 	core/PeakController.cpp
+	core/PerfLog.cpp
 	core/Piano.cpp
 	core/PlayHandle.cpp
 	core/Plugin.cpp

src/core/PerfLog.cpp

@@ -0,0 +1,131 @@
+/*
+ * PerfLog.cpp - Small performance logger
+ *
+ * Copyright (c) 2017-2018 LMMS Developers
+ *
+ * This file is part of LMMS - https://lmms.io
+ *
+ * This program is free software; you can redistribute it and/or
+ * modify it under the terms of the GNU General Public
+ * License as published by the Free Software Foundation; either
+ * version 2 of the License, or (at your option) any later version.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
+ * General Public License for more details.
+ *
+ * You should have received a copy of the GNU General Public
+ * License along with this program (see COPYING); if not, write to the
+ * Free Software Foundation, Inc., 51 Franklin Street, Fifth Floor,
+ * Boston, MA 02110-1301 USA.
+ *
+ */
+
+#include "PerfLog.h"
+
+#include "lmmsconfig.h"
+
+#if defined(LMMS_HAVE_SYS_TIMES_H) && defined(LMMS_HAVE_UNISTD_H)
+#	define USE_POSIX_TIME
+#endif
+
+#ifdef USE_POSIX_TIME
+#	include <unistd.h>
+#	include <sys/times.h>
+#endif
+
+PerfTime::PerfTime()
+	: m_real(-1)
+{
+}
+
+clock_t PerfTime::real() const
+{
+	return m_real;
+}
+
+clock_t PerfTime::user() const
+{
+	return m_user;
+}
+
+clock_t PerfTime::system() const
+{
+	return m_system;
+}
+
+bool PerfTime::valid() const
+{
+	return m_real != -1;
+}
+
+PerfTime PerfTime::now()
+{
+	PerfTime time;
+#ifdef USE_POSIX_TIME
+	tms t;
+	time.m_real = times(&t);
+	time.m_user = t.tms_utime;
+	time.m_system = t.tms_stime;
+	if (time.m_real == -1) { qWarning("PerfTime: now failed"); }
+#endif
+	return time;
+}
+
+clock_t PerfTime::ticksPerSecond()
+{
+	static long clktck = 0;
+#ifdef USE_POSIX_TIME
+	if (!clktck) {
+		if ((clktck = sysconf(_SC_CLK_TCK)) < 0) {
+			qWarning("PerfLog::end sysconf()");
+		}
+	}
+#endif
+	return clktck;
+}
+
+PerfTime operator-(const PerfTime& lhs, const PerfTime& rhs)
+{
+	PerfTime diff;
+	diff.m_real = lhs.m_real - rhs.m_real;
+	diff.m_user = lhs.m_user - rhs.m_user;
+	diff.m_system = lhs.m_system - rhs.m_system;
+	return diff;
+}
+
+PerfLogTimer::PerfLogTimer(const QString& what)
+	: name(what)
+{
+	begin();
+}
+
+PerfLogTimer::~PerfLogTimer()
+{
+	end();
+}
+
+void PerfLogTimer::begin()
+{
+	begin_time = PerfTime::now();
+}
+
+void PerfLogTimer::end()
+{
+	if (! begin_time.valid()) {
+		return;
+	}
+
+	long clktck = PerfTime::ticksPerSecond();
+
+	PerfTime d = PerfTime::now() - begin_time;
+	qWarning("PERFLOG | %20s | %.2fuser, %.2fsystem %.2felapsed",
+			 qPrintable(name),
+			 d.user() / (double)clktck,
+			 d.system() / (double)clktck,
+			 d.real() / (double)clktck);
+
+	// Invalidate so destructor won't call print another log entry
+	begin_time = PerfTime();
+}

src/core/ProjectRenderer.cpp

@@ -27,6 +27,7 @@
 
 #include "ProjectRenderer.h"
 #include "Song.h"
+#include "PerfLog.h"
 
 #include "AudioFileWave.h"
 #include "AudioFileOgg.h"
@@ -177,6 +178,8 @@ void ProjectRenderer::run()
 #endif
 #endif
 
+	PerfLogTimer perfLog("Project Render");
+
 	Engine::getSong()->startExport();
 	Engine::getSong()->updateLength();
 	// Skip first empty buffer.
@@ -209,6 +212,8 @@ void ProjectRenderer::run()
 
 	Engine::getSong()->stopExport();
 
+	perfLog.end();
+
 	// If the user aborted export-process, the file has to be deleted.
 	const QString f = m_fileDev->outputFile();
 	if( m_abort )

src/lmmsconfig.h.in

@@ -36,6 +36,7 @@
 #cmakedefine LMMS_HAVE_SEMAPHORE_H
 #cmakedefine LMMS_HAVE_SYS_SHM_H
 #cmakedefine LMMS_HAVE_SYS_TIME_H
+#cmakedefine LMMS_HAVE_SYS_TIMES_H
 #cmakedefine LMMS_HAVE_SCHED_H
 #cmakedefine LMMS_HAVE_SYS_SOUNDCARD_H
 #cmakedefine LMMS_HAVE_SOUNDCARD_H