logger: add mission file to LogWriterFile backend

Not used yet, it should not affect anything, except for slight RAM
increase.

src/modules/logger/log_writer.cpp

@@ -100,7 +100,7 @@ bool LogWriter::is_started() const
 	bool ret = false;
 
 	if (_log_writer_file) {
-		ret = _log_writer_file->is_started();
+		ret = _log_writer_file->is_started(LogType::Full);
 	}
 
 	if (_log_writer_mavlink) {
@@ -113,7 +113,7 @@ bool LogWriter::is_started() const
 bool LogWriter::is_started(Backend query_backend) const
 {
 	if (query_backend == BackendFile && _log_writer_file) {
-		return _log_writer_file->is_started();
+		return _log_writer_file->is_started(LogType::Full);
 	}
 
 	if (query_backend == BackendMavlink && _log_writer_mavlink) {
@@ -126,14 +126,14 @@ bool LogWriter::is_started(Backend query_backend) const
 void LogWriter::start_log_file(const char *filename)
 {
 	if (_log_writer_file) {
-		_log_writer_file->start_log(filename);
+		_log_writer_file->start_log(LogType::Full, filename);
 	}
 }
 
 void LogWriter::stop_log_file()
 {
 	if (_log_writer_file) {
-		_log_writer_file->stop_log();
+		_log_writer_file->stop_log(LogType::Full);
 	}
 }
 
@@ -163,7 +163,7 @@ int LogWriter::write_message(void *ptr, size_t size, uint64_t dropout_start)
 	int ret_file = 0, ret_mavlink = 0;
 
 	if (_log_writer_file_for_write) {
-		ret_file = _log_writer_file_for_write->write_message(ptr, size, dropout_start);
+		ret_file = _log_writer_file_for_write->write_message(LogType::Full, ptr, size, dropout_start);
 	}
 
 	if (_log_writer_mavlink_for_write) {

src/modules/logger/log_writer.h

@@ -118,21 +118,21 @@ public:
 
 	size_t get_total_written_file() const
 	{
-		if (_log_writer_file) { return _log_writer_file->get_total_written(); }
+		if (_log_writer_file) { return _log_writer_file->get_total_written(LogType::Full); }
 
 		return 0;
 	}
 
 	size_t get_buffer_size_file() const
 	{
-		if (_log_writer_file) { return _log_writer_file->get_buffer_size(); }
+		if (_log_writer_file) { return _log_writer_file->get_buffer_size(LogType::Full); }
 
 		return 0;
 	}
 
 	size_t get_buffer_fill_count_file() const
 	{
-		if (_log_writer_file) { return _log_writer_file->get_buffer_fill_count(); }
+		if (_log_writer_file) { return _log_writer_file->get_buffer_fill_count(LogType::Full); }
 
 		return 0;
 	}

src/modules/logger/log_writer_file.cpp

@@ -51,17 +51,21 @@ namespace logger
 {
 constexpr size_t LogWriterFile::_min_write_chunk;
 
-
-LogWriterFile::LogWriterFile(size_t buffer_size) :
+LogWriterFile::LogWriterFile(size_t buffer_size)
+	: _buffers{
 	//We always write larger chunks (orb messages) to the buffer, so the buffer
 	//needs to be larger than the minimum write chunk (300 is somewhat arbitrary)
-	_buffer_size(math::max(buffer_size, _min_write_chunk + 300))
+	{
+		math::max(buffer_size, _min_write_chunk + 300),
+		perf_alloc(PC_ELAPSED, "logger_sd_write"), perf_alloc(PC_ELAPSED, "logger_sd_fsync")},
+
+	{
+		300, // buffer size for the mission log (can be kept fairly small)
+		perf_alloc(PC_ELAPSED, "logger_sd_write_mission"), perf_alloc(PC_ELAPSED, "logger_sd_fsync_mission")}
+}
 {
 	pthread_mutex_init(&_mtx, nullptr);
 	pthread_cond_init(&_cv, nullptr);
-	/* allocate write performance counters */
-	_perf_write = perf_alloc(PC_ELAPSED, "logger_sd_write");
-	_perf_fsync = perf_alloc(PC_ELAPSED, "logger_sd_fsync");
 }
 
 bool LogWriterFile::init()
@@ -73,59 +77,26 @@ LogWriterFile::~LogWriterFile()
 {
 	pthread_mutex_destroy(&_mtx);
 	pthread_cond_destroy(&_cv);
-	perf_free(_perf_write);
-	perf_free(_perf_fsync);
-
-	if (_fd >= 0) {
-		::close(_fd);
-	}
-
-	if (_buffer) {
-		delete[] _buffer;
-	}
 }
 
-void LogWriterFile::start_log(const char *filename)
+void LogWriterFile::start_log(LogType type, const char *filename)
 {
-	// register the current file with the hardfault handler: if the system crashes,
-	// the hardfault handler will append the crash log to that file on the next reboot.
-	// Note that we don't deregister it when closing the log, so that crashes after disarming
-	// are appended as well (the same holds for crashes before arming, which can be a bit misleading)
-	int ret = hardfault_store_filename(filename);
-
-	if (ret) {
-		PX4_ERR("Failed to register ULog file to the hardfault handler (%i)", ret);
-	}
-
-	_fd = ::open(filename, O_CREAT | O_WRONLY, PX4_O_MODE_666);
-
-	if (_fd < 0) {
-		PX4_ERR("Can't open log file %s, errno: %d", filename, errno);
-		_should_run = false;
-		return;
-	}
-
-	if (_buffer == nullptr) {
-		_buffer = new uint8_t[_buffer_size];
-
-		if (_buffer == nullptr) {
-			PX4_ERR("Can't create log buffer");
-			::close(_fd);
-			_fd = -1;
-			_should_run = false;
-			return;
+	if (type == LogType::Full) {
+		// register the current file with the hardfault handler: if the system crashes,
+		// the hardfault handler will append the crash log to that file on the next reboot.
+		// Note that we don't deregister it when closing the log, so that crashes after disarming
+		// are appended as well (the same holds for crashes before arming, which can be a bit misleading)
+		int ret = hardfault_store_filename(filename);
+
+		if (ret) {
+			PX4_ERR("Failed to register ULog file to the hardfault handler (%i)", ret);
 		}
 	}
 
-	PX4_INFO("Opened log file: %s", filename);
-	_should_run = true;
-	_running = true;
-
-	// Clear buffer and counters
-	_head = 0;
-	_count = 0;
-	_total_written = 0;
-	notify();
+	if (_buffers[(int)type].start_log(filename)) {
+		PX4_INFO("Opened %s log file: %s", log_type_str(type), filename);
+		notify();
+	}
 }
 
 int LogWriterFile::hardfault_store_filename(const char *log_file)
@@ -160,9 +131,9 @@ int LogWriterFile::hardfault_store_filename(const char *log_file)
 	return 0;
 }
 
-void LogWriterFile::stop_log()
+void LogWriterFile::stop_log(LogType type)
 {
-	_should_run = false;
+	_buffers[(int)type]._should_run = false;
 	notify();
 }
 
@@ -188,7 +159,7 @@ void LogWriterFile::thread_stop()
 {
 	// this will terminate the main loop of the writer thread
 	_exit_thread = true;
-	_should_run = false;
+	_buffers[0]._should_run = _buffers[1]._should_run = false;
 
 	notify();
 
@@ -218,7 +189,7 @@ void LogWriterFile::run()
 			bool start = false;
 			pthread_mutex_lock(&_mtx);
 			pthread_cond_wait(&_cv, &_mtx);
-			start = _should_run;
+			start = _buffers[0]._should_run || _buffers[1]._should_run;
 			pthread_mutex_unlock(&_mtx);
 
 			if (start) {
@@ -234,95 +205,95 @@ void LogWriterFile::run()
 		int written = 0;
 		hrt_abstime last_fsync = hrt_absolute_time();
 
+		pthread_mutex_lock(&_mtx);
+
 		while (true) {
-			size_t available = 0;
-			void *read_ptr = nullptr;
-			bool is_part = false;
 
-			/* lock _buffer
-			 * wait for sufficient data, cycle on notify()
-			 */
-			pthread_mutex_lock(&_mtx);
+			const hrt_abstime now = hrt_absolute_time();
 
-			while (true) {
-				available = get_read_ptr(&read_ptr, &is_part);
+			/* call fsync periodically to minimize potential loss of data */
+			const bool call_fsync = ++poll_count >= 100 || now - last_fsync > 1_s;
 
-				/* if sufficient data available or partial read or terminating, exit this wait loop */
-				if ((available >= _min_write_chunk) || is_part || !_should_run) {
-					/* GOTO end of block */
-					break;
-				}
-
-				/* wait for a call to notify()
-				 * this call unlocks the mutex while waiting, and returns with the mutex locked
-				 */
-				pthread_cond_wait(&_cv, &_mtx);
+			if (call_fsync) {
+				last_fsync = now;
+				poll_count = 0;
 			}
 
-			pthread_mutex_unlock(&_mtx);
-			written = 0;
-
-			if (available > 0) {
-				perf_begin(_perf_write);
-				written = ::write(_fd, read_ptr, available);
-				perf_end(_perf_write);
-
-				const hrt_abstime now = hrt_absolute_time();
-
-				/* call fsync periodically to minimize potential loss of data */
-				if (++poll_count >= 100 || now - last_fsync > 1_s) {
-					perf_begin(_perf_fsync);
-					::fsync(_fd);
-					perf_end(_perf_fsync);
-					poll_count = 0;
-					last_fsync = now;
-				}
+			constexpr size_t min_available[(int)LogType::Count] = {
+				_min_write_chunk,
+				1 // For the mission log, write as soon as there is data available
+			};
 
-				if (written < 0) {
-					PX4_WARN("error writing log file");
-					_should_run = false;
-					/* GOTO end of block */
-					break;
-				}
+			/* Check all buffers for available data. Mission log is first to avoid drops */
+			int i = (int)LogType::Count - 1;
 
-				pthread_mutex_lock(&_mtx);
-				/* subtract bytes written from number in _buffer (_count -= written) */
-				mark_read(written);
-				pthread_mutex_unlock(&_mtx);
+			while (i >= 0) {
+				void *read_ptr;
+				bool is_part;
+				LogFileBuffer &buffer = _buffers[i];
+				size_t available = buffer.get_read_ptr(&read_ptr, &is_part);
 
-				_total_written += written;
-			}
+				/* if sufficient data available or partial read or terminating, write data */
+				if (available >= min_available[i] || is_part || (!buffer._should_run && available > 0)) {
+					pthread_mutex_unlock(&_mtx);
+
+					written = buffer.write_to_file(read_ptr, available, call_fsync);
 
-			if (!_should_run && written == static_cast<int>(available) && !is_part) {
-				// Stop only when all data written
-				_running = false;
-				_head = 0;
-				_count = 0;
+					/* buffer.mark_read() requires _mtx to be locked */
+					pthread_mutex_lock(&_mtx);
 
-				if (_fd >= 0) {
-					int res = ::close(_fd);
-					_fd = -1;
+					if (written >= 0) {
+						/* subtract bytes written from number in buffer (count -= written) */
+						buffer.mark_read(written);
 
-					if (res) {
-						PX4_WARN("error closing log file");
+						if (!buffer._should_run && written == static_cast<int>(available) && !is_part) {
+							/* Stop only when all data written */
+							buffer.close_file();
+						}
 
 					} else {
-						PX4_INFO("closed logfile, bytes written: %zu", _total_written);
+						PX4_ERR("write failed (%i)", errno);
+						buffer._should_run = false;
+						buffer.close_file();
 					}
+
+				} else if (call_fsync) {
+					buffer.fsync();
+
+				} else if (available == 0 && !buffer._should_run) {
+					buffer.close_file();
+				}
+
+				/* if split into 2 parts, write the second part immediately as well */
+				if (!is_part) {
+					--i;
 				}
+			}
 
+
+			if (_buffers[0].fd() < 0 && _buffers[1].fd() < 0) {
+				// stop when both files are closed
 				break;
 			}
+
+			/* Wait for a call to notify(), which indicates new data is available.
+			 * Note that at this point there could already be new data available (because of a longer write),
+			 * and calling pthread_cond_wait() will still wait for the next notify(). But this is generally
+			 * not an issue because notify() is called regularly. */
+			pthread_cond_wait(&_cv, &_mtx);
 		}
+
+		// go back to idle
+		pthread_mutex_unlock(&_mtx);
 	}
 }
 
-int LogWriterFile::write_message(void *ptr, size_t size, uint64_t dropout_start)
+int LogWriterFile::write_message(LogType type, void *ptr, size_t size, uint64_t dropout_start)
 {
 	if (_need_reliable_transfer) {
 		int ret;
 
-		while ((ret = write(ptr, size, dropout_start)) == -1) {
+		while ((ret = write(type, ptr, size, dropout_start)) == -1) {
 			unlock();
 			notify();
 			usleep(3000);
@@ -332,17 +303,17 @@ int LogWriterFile::write_message(void *ptr, size_t size, uint64_t dropout_start)
 		return ret;
 	}
 
-	return write(ptr, size, dropout_start);
+	return write(type, ptr, size, dropout_start);
 }
 
-int LogWriterFile::write(void *ptr, size_t size, uint64_t dropout_start)
+int LogWriterFile::write(LogType type, void *ptr, size_t size, uint64_t dropout_start)
 {
-	if (!is_started()) {
+	if (!is_started(type)) {
 		return 0;
 	}
 
 	// Bytes available to write
-	size_t available = _buffer_size - _count;
+	size_t available = _buffers[(int)type].available();
 	size_t dropout_size = 0;
 
 	if (dropout_start) {
@@ -358,14 +329,44 @@ int LogWriterFile::write(void *ptr, size_t size, uint64_t dropout_start)
 		//write dropout msg
 		ulog_message_dropout_s dropout_msg;
 		dropout_msg.duration = (uint16_t)(hrt_elapsed_time(&dropout_start) / 1000);
-		write_no_check(&dropout_msg, sizeof(dropout_msg));
+		_buffers[(int)type].write_no_check(&dropout_msg, sizeof(dropout_msg));
 	}
 
-	write_no_check(ptr, size);
+	_buffers[(int)type].write_no_check(ptr, size);
 	return 0;
 }
 
-void LogWriterFile::write_no_check(void *ptr, size_t size)
+const char *log_type_str(LogType type)
+{
+	switch (type) {
+	case LogType::Full: return "full";
+
+	case LogType::Mission: return "mission";
+
+	case LogType::Count: break;
+	}
+
+	return "unknown";
+}
+
+LogWriterFile::LogFileBuffer::LogFileBuffer(size_t buffer_size, perf_counter_t perf_write, perf_counter_t perf_fsync)
+	: _buffer_size(buffer_size), _perf_write(perf_write), _perf_fsync(perf_fsync)
+{
+}
+
+LogWriterFile::LogFileBuffer::~LogFileBuffer()
+{
+	if (_fd >= 0) {
+		close(_fd);
+	}
+
+	delete[] _buffer;
+
+	perf_free(_perf_write);
+	perf_free(_perf_fsync);
+}
+
+void LogWriterFile::LogFileBuffer::write_no_check(void *ptr, size_t size)
 {
 	size_t n = _buffer_size - _head;	// bytes to end of the buffer
 
@@ -387,7 +388,7 @@ void LogWriterFile::write_no_check(void *ptr, size_t size)
 	_count += size;
 }
 
-size_t LogWriterFile::get_read_ptr(void **ptr, bool *is_part)
+size_t LogWriterFile::LogFileBuffer::get_read_ptr(void **ptr, bool *is_part)
 {
 	// bytes available to read
 	int read_ptr = _head - _count;
@@ -405,5 +406,73 @@ size_t LogWriterFile::get_read_ptr(void **ptr, bool *is_part)
 	}
 }
 
+bool LogWriterFile::LogFileBuffer::start_log(const char *filename)
+{
+	_fd = ::open(filename, O_CREAT | O_WRONLY, PX4_O_MODE_666);
+
+	if (_fd < 0) {
+		PX4_ERR("Can't open log file %s, errno: %d", filename, errno);
+		return false;
+	}
+
+	if (_buffer == nullptr) {
+		_buffer = new uint8_t[_buffer_size];
+
+		if (_buffer == nullptr) {
+			PX4_ERR("Can't create log buffer");
+			::close(_fd);
+			_fd = -1;
+			return false;
+		}
+	}
+
+	// Clear buffer and counters
+	_head = 0;
+	_count = 0;
+	_total_written = 0;
+
+	_should_run = true;
+
+	return true;
+}
+
+void LogWriterFile::LogFileBuffer::fsync() const
+{
+	perf_begin(_perf_fsync);
+	::fsync(_fd);
+	perf_end(_perf_fsync);
+}
+
+ssize_t LogWriterFile::LogFileBuffer::write_to_file(const void *buffer, size_t size, bool call_fsync) const
+{
+	perf_begin(_perf_write);
+	ssize_t ret = ::write(_fd, buffer, size);
+	perf_end(_perf_write);
+
+	if (call_fsync) {
+		fsync();
+	}
+
+	return ret;
+}
+
+void LogWriterFile::LogFileBuffer::close_file()
+{
+	_head = 0;
+	_count = 0;
+
+	if (_fd >= 0) {
+		int res = close(_fd);
+		_fd = -1;
+
+		if (res) {
+			PX4_WARN("closing log file failed (%i)", errno);
+
+		} else {
+			PX4_INFO("closed logfile, bytes written: %zu", _total_written);
+		}
+	}
+}
+
 }
 }

src/modules/logger/log_writer_file.h

@@ -44,6 +44,19 @@ namespace px4
 namespace logger
 {
 
+/**
+ * @enum LogType
+ * Defines different log (file) types
+ */
+enum class LogType {
+	Full = 0, //!< Normal, full size log
+	Mission,  //!< reduced mission log (e.g. for geotagging)
+
+	Count
+};
+
+const char *log_type_str(LogType type);
+
 /**
  * @class LogWriterFile
  * Writes logging data to a file
@@ -64,14 +77,14 @@ public:
 
 	void thread_stop();
 
-	void start_log(const char *filename);
+	void start_log(LogType type, const char *filename);
 
-	void stop_log();
+	void stop_log(LogType type);
 
-	bool is_started() const { return _should_run; }
+	bool is_started(LogType type) const { return _buffers[(int)type]._should_run; }
 
 	/** @see LogWriter::write_message() */
-	int write_message(void *ptr, size_t size, uint64_t dropout_start = 0);
+	int write_message(LogType type, void *ptr, size_t size, uint64_t dropout_start = 0);
 
 	void lock()
 	{
@@ -88,19 +101,19 @@ public:
 		pthread_cond_broadcast(&_cv);
 	}
 
-	size_t get_total_written() const
+	size_t get_total_written(LogType type) const
 	{
-		return _total_written;
+		return _buffers[(int)type].total_written();
 	}
 
-	size_t get_buffer_size() const
+	size_t get_buffer_size(LogType type) const
 	{
-		return _buffer_size;
+		return _buffers[(int)type].buffer_size();
 	}
 
-	size_t get_buffer_fill_count() const
+	size_t get_buffer_fill_count(LogType type) const
 	{
-		return _count;
+		return _buffers[(int)type].count();
 	}
 
 	void set_need_reliable_transfer(bool need_reliable)
@@ -120,13 +133,6 @@ private:
 
 	void run();
 
-	size_t get_read_ptr(void **ptr, bool *is_part);
-
-	void mark_read(size_t n)
-	{
-		_count -= n;
-	}
-
 	/**
 	 * permanently store the ulog file name for the hardfault crash handler, so that it can
 	 * append crash logs to the last ulog file.
@@ -138,30 +144,62 @@ private:
 	/**
 	 * write w/o waiting/blocking
 	 */
-	int write(void *ptr, size_t size, uint64_t dropout_start);
-
-	/**
-	 * Write to the buffer but assuming there is enough space
-	 */
-	inline void write_no_check(void *ptr, size_t size);
+	int write(LogType type, void *ptr, size_t size, uint64_t dropout_start);
 
 	/* 512 didn't seem to work properly, 4096 should match the FAT cluster size */
 	static constexpr size_t	_min_write_chunk = 4096;
 
-	int			_fd = -1;
-	uint8_t 	*_buffer = nullptr;
-	const size_t	_buffer_size;
-	size_t			_head = 0; ///< next position to write to
-	size_t			_count = 0; ///< number of bytes in _buffer to be written
-	size_t		_total_written = 0;
-	bool		_should_run = false;
-	bool		_running = false;
+	class LogFileBuffer
+	{
+	public:
+		LogFileBuffer(size_t buffer_size, perf_counter_t perf_write, perf_counter_t perf_fsync);
+
+		~LogFileBuffer();
+
+		bool start_log(const char *filename);
+
+		void close_file();
+
+		size_t get_read_ptr(void **ptr, bool *is_part);
+
+		/**
+		 * Write to the buffer but assuming there is enough space
+		 */
+		inline void write_no_check(void *ptr, size_t size);
+
+		size_t available() const { return _buffer_size - _count; }
+
+		int fd() const { return _fd; }
+
+		inline ssize_t write_to_file(const void *buffer, size_t size, bool call_fsync) const;
+
+		inline void fsync() const;
+
+		void mark_read(size_t n) { _count -= n; _total_written += n; }
+
+		size_t total_written() const { return _total_written; }
+		size_t buffer_size() const { return _buffer_size; }
+		size_t count() const { return _count; }
+
+		bool _should_run = false;
+
+	private:
+		const size_t _buffer_size;
+		int	_fd = -1;
+		uint8_t *_buffer = nullptr;
+		size_t _head = 0; ///< next position to write to
+		size_t _count = 0; ///< number of bytes in _buffer to be written
+		size_t _total_written = 0;
+		perf_counter_t _perf_write;
+		perf_counter_t _perf_fsync;
+	};
+
+	LogFileBuffer _buffers[(int)LogType::Count];
+
 	bool 		_exit_thread = false;
 	bool		_need_reliable_transfer = false;
 	pthread_mutex_t		_mtx;
 	pthread_cond_t		_cv;
-	perf_counter_t _perf_write;
-	perf_counter_t _perf_fsync;
 	pthread_t _thread = 0;
 };