HaikuDepot: Log Process Report

To make it easier to understand what process
elements are taking a long time to run, a
small simple report is output as debug log
at completion of a process.

Change-Id: I09b93c494961e7abbbd22a3c58c64631f08025af
Reviewed-on: https://review.haiku-os.org/c/haiku/+/7075
Reviewed-by: Jérôme Duval <jerome.duval@gmail.com>

src/apps/haikudepot/model/PackageIconTarRepository.cpp

@@ -9,7 +9,7 @@
 #include <Autolock.h>
 #include <AutoDeleter.h>
 #include <File.h>
-#include <support/StopWatch.h>
+#include <StopWatch.h>
 
 #include "Logger.h"
 #include "TarArchiveService.h"

src/apps/haikudepot/process/AbstractProcess.cpp

@@ -11,6 +11,7 @@
 #include <AutoDeleter.h>
 #include <AutoLocker.h>
 #include <Locker.h>
+#include <StopWatch.h>
 
 #include "HaikuDepotConstants.h"
 #include "Logger.h"
@@ -23,7 +24,8 @@ AbstractProcess::AbstractProcess()
 	fListener(NULL),
 	fWasStopped(false),
 	fProcessState(PROCESS_INITIAL),
-	fErrorStatus(B_OK)
+	fErrorStatus(B_OK),
+	fDurationSeconds(0.0)
 {
 }
 
@@ -68,7 +70,9 @@ AbstractProcess::Run()
 	if (listener != NULL)
 		listener->ProcessChanged();
 
+	BStopWatch stopWatch("process", true);
 	status_t runResult = RunInternal();
+	fDurationSeconds = ((double) stopWatch.ElapsedTime() / 1000000.0);
 
 	if (runResult != B_OK)
 		HDERROR("[%s] an error has arisen; %s", Name(), strerror(runResult));
@@ -179,3 +183,30 @@ AbstractProcess::_NotifyChanged()
 	if (listener != NULL)
 		listener->ProcessChanged();
 }
+
+
+BString
+AbstractProcess::LogReport()
+{
+	BString result;
+	AutoLocker<BLocker> locker(&fLock);
+	result.SetToFormat("%s [%c] %6.3f", Name(), _ProcessStateIdentifier(ProcessState()),
+		fDurationSeconds);
+	return result;
+}
+
+
+/*static*/ char
+AbstractProcess::_ProcessStateIdentifier(process_state value)
+{
+	switch (value) {
+		case PROCESS_INITIAL:
+			return 'I';
+		case PROCESS_RUNNING:
+			return 'R';
+		case PROCESS_COMPLETE:
+			return 'C';
+		default:
+			return '?';
+	}
+}

src/apps/haikudepot/process/AbstractProcess.h

@@ -39,6 +39,8 @@ public:
 			bool				WasStopped();
 			process_state		ProcessState();
 
+	virtual	BString				LogReport();
+
 			void				SetListener(ProcessListener* listener);
 
 protected:
@@ -46,6 +48,8 @@ protected:
 	virtual	status_t			StopInternal();
 			void				_NotifyChanged();
 
+	static	char				_ProcessStateIdentifier(process_state value);
+
 protected:
 			BLocker				fLock;
 
@@ -54,6 +58,7 @@ private:
 			bool				fWasStopped;
 			process_state		fProcessState;
 			status_t			fErrorStatus;
+			double				fDurationSeconds;
 };
 
 #endif // ABSTRACT_PROCESS_H

src/apps/haikudepot/process/AbstractProcessNode.cpp

@@ -139,3 +139,9 @@ AbstractProcessNode::SuccessorAt(int32 index) const
 	return fSuccessorNodes.ItemAt(index);
 }
 
+
+BString
+AbstractProcessNode::LogReport()
+{
+	return Process()->LogReport();
+}

src/apps/haikudepot/process/AbstractProcessNode.h

@@ -10,6 +10,7 @@
 #include <Locker.h>
 #include <ObjectList.h>
 #include <OS.h>
+#include <String.h>
 
 
 class AbstractProcess;
@@ -43,6 +44,8 @@ public:
 
 	virtual	void				SetListener(ProcessListener* listener);
 
+			BString				LogReport();
+
 protected:
 			status_t			_SpinUntilProcessState(
 									uint32 desiredStatesMask,

src/apps/haikudepot/process/ProcessCoordinator.cpp

@@ -459,3 +459,20 @@ ProcessCoordinator::_CountNodesCompleted()
 	}
 	return nodesCompleted;
 }
+
+
+BString
+ProcessCoordinator::LogReport()
+{
+	BString result;
+	AutoLocker<BLocker> locker(&fLock);
+
+	for (int32 i = 0; i < fNodes.CountItems(); i++) {
+		if (0 != result.Length())
+			result.Append("\n");
+		AbstractProcessNode* node = fNodes.ItemAt(i);
+		result.Append(node->LogReport());
+	}
+
+	return result;
+}

src/apps/haikudepot/process/ProcessCoordinator.h

@@ -109,6 +109,8 @@ public:
 
 			float				Progress();
 
+			BString				LogReport();
+
 	const	BString&			Name() const;
 			BMessage*			Message() const;
 

src/apps/haikudepot/server/AbstractSingleFileServerProcess.cpp

@@ -6,6 +6,9 @@
 
 #include "AbstractSingleFileServerProcess.h"
 
+#include <AutoLocker.h>
+#include <StopWatch.h>
+
 #include "HaikuDepotConstants.h"
 #include "Logger.h"
 #include "ServerHelper.h"
@@ -16,7 +19,9 @@
 AbstractSingleFileServerProcess::AbstractSingleFileServerProcess(
 	uint32 options)
 	:
-	AbstractServerProcess(options)
+	AbstractServerProcess(options),
+	fDownloadDurationSeconds(0.0),
+    fProcessLocalDataDurationSeconds(0.0)
 {
 }
 
@@ -50,9 +55,11 @@ AbstractSingleFileServerProcess::RunInternal()
 	hasData = hasData && size > 0;
 
 	if (IsSuccess(result) && ShouldAttemptNetworkDownload(hasData)) {
+		BStopWatch stopWatch("download", true);
 		result = DownloadToLocalFileAtomically(
 			localPath,
 			ServerSettings::CreateFullUrl(urlPathComponent));
+		fDownloadDurationSeconds = ((double) stopWatch.ElapsedTime() / 1000000.0);
 
 		if (!IsSuccess(result)) {
 			if (hasData) {
@@ -77,7 +84,10 @@ AbstractSingleFileServerProcess::RunInternal()
 
 	if (IsSuccess(result)) {
 		HDINFO("[%s] will process data", Name());
+
+		BStopWatch stopWatch("process local data", true);
 		result = ProcessLocalData();
+		fProcessLocalDataDurationSeconds = ((double) stopWatch.ElapsedTime() / 1000000.0);
 
 		switch (result) {
 			case B_OK:
@@ -99,3 +109,26 @@ AbstractSingleFileServerProcess::GetStandardMetaDataPath(BPath& path) const
 {
 	return GetLocalPath(path);
 }
+
+
+BString
+AbstractSingleFileServerProcess::LogReport()
+{
+	BString result;
+	result.Append(AbstractProcess::LogReport());
+
+	AutoLocker<BLocker> locker(&fLock);
+
+	if (ProcessState() == PROCESS_COMPLETE) {
+		BString downloadLogLine;
+		BString localDataLogLine;
+		downloadLogLine.SetToFormat("\n - download %6.3f",
+			fDownloadDurationSeconds);
+		localDataLogLine.SetToFormat("\n - process local data %6.3f",
+			fProcessLocalDataDurationSeconds);
+		result.Append(downloadLogLine);
+		result.Append(localDataLogLine);
+	}
+
+	return result;
+}

src/apps/haikudepot/server/AbstractSingleFileServerProcess.h

@@ -16,6 +16,8 @@ public:
 								AbstractSingleFileServerProcess(uint32 options);
 	virtual						~AbstractSingleFileServerProcess();
 
+	virtual	BString				LogReport();
+
 protected:
 	virtual status_t			RunInternal();
 
@@ -26,6 +28,10 @@ protected:
 	virtual	status_t			GetLocalPath(BPath& path) const = 0;
 
 	virtual	status_t			GetStandardMetaDataPath(BPath& path) const;
+
+protected:
+			double				fDownloadDurationSeconds;
+			double				fProcessLocalDataDurationSeconds;
 };
 
 #endif // ABSTRACT_SINGLE_FILE_SERVER_PROCESS_H

src/apps/haikudepot/server/ServerPkgDataUpdateProcess.cpp

@@ -14,7 +14,7 @@
 #include <AutoLocker.h>
 #include <Catalog.h>
 #include <FileIO.h>
-#include <support/StopWatch.h>
+#include <StopWatch.h>
 #include <Url.h>
 
 #include "Logger.h"

src/apps/haikudepot/ui/MainWindow.cpp

@@ -1608,6 +1608,9 @@ MainWindow::_HandleProcessCoordinatorChanged(ProcessCoordinatorState& coordinato
 				messenger.SendMessage(message);
 			}
 
+			HDDEBUG("process coordinator report;\n---\n%s\n----",
+				fCoordinator->LogReport().String());
+
 			delete fCoordinator;
 			fCoordinator = NULL;