Log elapsed time for multiprocessrollingappender unit test

src/main/cpp/multiprocessrollingfileappender.cpp

@@ -37,6 +37,12 @@
 #include <mutex>
 #include <thread>
 
+#ifdef WIN32 // apr_stat is slow on Windows
+#define USING_ROLLOVER_REQUIRED_CHECK_IS_FASTER 1
+#else
+#define USING_ROLLOVER_REQUIRED_CHECK_IS_FASTER 0
+#endif
+
 using namespace LOG4CXX_NS;
 using namespace LOG4CXX_NS::rolling;
 using namespace LOG4CXX_NS::helpers;
@@ -158,7 +164,7 @@ void MultiprocessRollingFileAppender::activateOptions(Pool& p)
 bool MultiprocessRollingFileAppender::isRolloverCheckNeeded()
 {
 	bool result = true;
-#ifdef WIN32 // apr_stat is slow on Windows
+#if USING_ROLLOVER_REQUIRED_CHECK_IS_FASTER
 	if (auto pTimeBased = LOG4CXX_NS::cast<TimeBasedRollingPolicy>(_priv->rollingPolicy))
 		result = !pTimeBased->isLastFileNameUnchanged();
 #endif
@@ -367,6 +373,10 @@ bool MultiprocessRollingFileAppender::synchronizedRollover(Pool& p, const Trigge
 void MultiprocessRollingFileAppender::reopenFile(const LogString& fileName)
 {
 	closeWriter();
+#if USING_ROLLOVER_REQUIRED_CHECK_IS_FASTER
+	if (auto pTimeBased = LOG4CXX_NS::cast<TimeBasedRollingPolicy>(_priv->rollingPolicy))
+		pTimeBased->loadLastFileName();
+#endif
 	OutputStreamPtr os = std::make_shared<FileOutputStream>(fileName, true);
 	WriterPtr newWriter(createWriter(os));
 	setFile(fileName);

src/main/cpp/timebasedrollingpolicy.cpp

@@ -550,3 +550,22 @@ bool TimeBasedRollingPolicy::isLastFileNameUnchanged()
 	}
 	return result;
 }
+
+/**
+ * Load the name (set by some other process) from shared memory
+ */
+void TimeBasedRollingPolicy::loadLastFileName()
+{
+	if( m_priv->multiprocess ){
+#if LOG4CXX_HAS_MULTIPROCESS_ROLLING_FILE_APPENDER
+		if (m_priv->_mmap)
+		{
+			lockMMapFile(APR_FLOCK_SHARED);
+			LogString mapLastFile((char*)m_priv->_mmap->mm);
+			unLockMMapFile();
+			if (!mapLastFile.empty())
+				m_priv->lastFileName = mapLastFile;
+		}
+#endif
+	}
+}

src/main/include/log4cxx/rolling/timebasedrollingpolicy.h

@@ -214,6 +214,11 @@ class LOG4CXX_EXPORT TimeBasedRollingPolicy : public virtual RollingPolicyBase,
 		 */
 		bool isLastFileNameUnchanged();
 
+		/**
+		 * Load the name (set by some other process) from shared memory
+		 */
+		void loadLastFileName();
+
 	protected:
 		/**
 		 * A map from "d" and "date" to a date conversion formatter.

src/test/cpp/rolling/multiprocessrollingtest.cpp

@@ -24,6 +24,7 @@
 #include <log4cxx/rolling/sizebasedtriggeringpolicy.h>
 #include <log4cxx/helpers/strftimedateformat.h>
 #include <log4cxx/helpers/date.h>
+#include <log4cxx/helpers/fileoutputstream.h>
 #include <log4cxx/helpers/loglog.h>
 #include <log4cxx/helpers/stringhelper.h>
 #include <filesystem>
@@ -109,7 +110,10 @@ LOGUNIT_CLASS(MultiprocessRollingTest)
 	{
 		std::string expectedPrefix = LOG4CXX_STR("multiprocess-2-");
 		// remove any previously generated files
-		for (auto const& dir_entry : std::filesystem::directory_iterator{"output/rolling"})
+		std::filesystem::path outputDir("output/rolling");
+		if (!exists(outputDir))
+			;
+		else for (auto const& dir_entry : std::filesystem::directory_iterator{outputDir})
 		{
 			std::string filename(dir_entry.path().filename().string());
 			if (expectedPrefix.size() < filename.size() &&
@@ -183,12 +187,14 @@ LOGUNIT_CLASS(MultiprocessRollingTest)
 				filename.substr(0, expectedPrefix.size()) == expectedPrefix)
 				std::filesystem::remove(dir_entry);
 		}
+		helpers::FileOutputStream output(LOG4CXX_STR("output/rolling/multiprocess-test4-child.log"), false);
 		auto thisProgram = GetExecutableFileName();
 		const char* args[] = {thisProgram.c_str(), "test3", 0};
 		helpers::Pool p;
 		apr_procattr_t* attr = NULL;
-		setTestAttributes(&attr, p);
+		setTestAttributes(&attr, output.getFilePtr(), p);
 		apr_proc_t pid[5];
+		auto startTime = helpers::Date::currentTime();
 		for (auto i : {0, 1, 2, 3, 4})
 			startTestInstance(&pid[i], attr, args, p);
 		for (auto i : {0, 1, 2, 3, 4})
@@ -198,6 +204,14 @@ LOGUNIT_CLASS(MultiprocessRollingTest)
 			apr_proc_wait(&pid[i], &exitCode, &reason, APR_WAIT);
 			LOGUNIT_ASSERT_EQUAL(exitCode, 0);
 		}
+		if (helpers::LogLog::isDebugEnabled())
+		{
+			LogString msg;
+			auto currentTime = helpers::Date::currentTime();
+			msg += LOG4CXX_STR("elapsed ");
+			helpers::StringHelper::toString(currentTime - startTime, p, msg);
+			helpers::LogLog::debug(msg);
+		}
 
 		// Check all messages are saved to files
 		std::string expectedSuffix(".log");
@@ -291,19 +305,23 @@ LOGUNIT_CLASS(MultiprocessRollingTest)
 
 private:
 
-	void setTestAttributes(apr_procattr_t** attr, helpers::Pool& p)
+	void setTestAttributes(apr_procattr_t** attr, apr_file_t* output, helpers::Pool& p)
 	{
 		if (apr_procattr_create(attr, p.getAPRPool()) != APR_SUCCESS)
 		{
-			LOGUNIT_FAIL("apr_procattr_create failed");
+			LOGUNIT_FAIL("apr_procattr_create");
+		}
+		if (apr_procattr_cmdtype_set(*attr, APR_PROGRAM) != APR_SUCCESS)
+		{
+			LOGUNIT_FAIL("apr_procattr_cmdtype_set");
 		}
-		if (apr_procattr_io_set(*attr, APR_NO_PIPE, APR_NO_PIPE, APR_NO_PIPE) != APR_SUCCESS)
+		if (apr_procattr_child_out_set(*attr, output, NULL) != APR_SUCCESS)
 		{
-			LOGUNIT_FAIL("apr_procattr_io_set failed");
+			LOGUNIT_FAIL("apr_procattr_child_out_set");
 		}
-		if (apr_procattr_cmdtype_set(*attr, APR_PROGRAM) != APR_SUCCESS)
+		if (apr_procattr_child_err_set(*attr, output, NULL) != APR_SUCCESS)
 		{
-			LOGUNIT_FAIL("apr_procattr_cmdtype_set failed");
+			LOGUNIT_FAIL("apr_procattr_child_err_set");
 		}
 	}
 
@@ -315,7 +333,7 @@ LOGUNIT_CLASS(MultiprocessRollingTest)
 		}
 		else
 		{
-			LOGUNIT_FAIL("apr_proc_create failed");
+			LOGUNIT_FAIL("apr_proc_create");
 		}
 	}