From 6acdb38d11dfc6ba741e7c0118341ebb0e52d7c2 Mon Sep 17 00:00:00 2001 From: Pablo Curiel Date: Fri, 3 May 2024 15:14:32 +0200 Subject: [PATCH] FileWriter: remove call to ftruncate() ftruncate() may severely delay the start of a dump process for certain UMS devices, and the write speed differences when using the SD card seem to be negligible. Other changes include: * FileWriter: add log messages throughout all class methods. * log: update generic log macros to use __PRETTY_FUNCTION__ instead of __func__. * log: add logFormatFunctionName() function, which takes an input __PRETTY_FUNCTION__ string and parses the info we need from it. * log: update _logWriteFormattedStringToLogFile() and logWriteFormattedStringToBuffer() functions to reflect the other changes. --- include/core/nxdt_log.h | 6 +- source/core/nxdt_log.c | 41 ++++++-- source/tasks/gamecard_image_dump_task.cpp | 1 + source/utils/file_writer.cpp | 110 +++++++++++++--------- 4 files changed, 103 insertions(+), 55 deletions(-) diff --git a/include/core/nxdt_log.h b/include/core/nxdt_log.h index d87a4a8..f6ec309 100644 --- a/include/core/nxdt_log.h +++ b/include/core/nxdt_log.h @@ -44,9 +44,9 @@ extern "C" { /// Helper macros. -#define LOG_MSG_GENERIC(level, fmt, ...) logWriteFormattedStringToLogFile(level, __FILE__, __LINE__, __func__, fmt, ##__VA_ARGS__) -#define LOG_MSG_BUF_GENERIC(dst, dst_size, level, fmt, ...) logWriteFormattedStringToBuffer(dst, dst_size, level, __FILE__, __LINE__, __func__, fmt, ##__VA_ARGS__) -#define LOG_DATA_GENERIC(data, data_size, level, fmt, ...) logWriteBinaryDataToLogFile(data, data_size, level, __FILE__, __LINE__, __func__, fmt, ##__VA_ARGS__) +#define LOG_MSG_GENERIC(level, fmt, ...) logWriteFormattedStringToLogFile(level, __FILE__, __LINE__, __PRETTY_FUNCTION__, fmt, ##__VA_ARGS__) +#define LOG_MSG_BUF_GENERIC(dst, dst_size, level, fmt, ...) logWriteFormattedStringToBuffer(dst, dst_size, level, __FILE__, __LINE__, __PRETTY_FUNCTION__, fmt, ##__VA_ARGS__) +#define LOG_DATA_GENERIC(data, data_size, level, fmt, ...) logWriteBinaryDataToLogFile(data, data_size, level, __FILE__, __LINE__, __PRETTY_FUNCTION__, fmt, ##__VA_ARGS__) #if LOG_LEVEL == LOG_LEVEL_DEBUG #define LOG_MSG_DEBUG(fmt, ...) LOG_MSG_GENERIC(LOG_LEVEL_DEBUG, fmt, ##__VA_ARGS__) diff --git a/source/core/nxdt_log.c b/source/core/nxdt_log.c index 71e312a..daf247d 100644 --- a/source/core/nxdt_log.c +++ b/source/core/nxdt_log.c @@ -35,7 +35,7 @@ static s64 g_logFileOffset = 0; static char *g_logBuffer = NULL; static size_t g_logBufferLength = 0; -static const char *g_logStrFormat = "[%d-%02d-%02d %02d:%02d:%02d.%09lu] [%s] %s:%d:%s -> "; +static const char *g_logStrFormat = "[%d-%02d-%02d %02d:%02d:%02d.%09lu] [%s] %s|%d|%s -> "; static const char *g_logSessionSeparator = "________________________________________________________________\r\n"; static const char *g_logLevelNames[] = { @@ -55,6 +55,8 @@ static void _logFlushLogFile(void); static bool logAllocateLogBuffer(void); static bool logOpenLogFile(void); +static void logFormatFunctionName(const char *func_name, char *out, size_t out_size); + static void logWriteStringToNxLink(const char *str); void logWriteStringToLogFile(const char *src) @@ -85,6 +87,9 @@ __attribute__((format(printf, 7, 8))) void logWriteFormattedStringToBuffer(char struct tm ts = {0}; struct timespec now = {0}; + char formatted_func_name[0x100] = {0}; + logFormatFunctionName(func_name, formatted_func_name, MAX_ELEMENTS(formatted_func_name)); + /* Sanity check. */ if (dst_cur_size && dst_str_len >= dst_cur_size) return; @@ -99,7 +104,7 @@ __attribute__((format(printf, 7, 8))) void logWriteFormattedStringToBuffer(char ts.tm_mon++; /* Get formatted string length. */ - str1_len = snprintf(NULL, 0, g_logStrFormat, ts.tm_year, ts.tm_mon, ts.tm_mday, ts.tm_hour, ts.tm_min, ts.tm_sec, now.tv_nsec, g_logLevelNames[level], file_name, line, func_name); + str1_len = snprintf(NULL, 0, g_logStrFormat, ts.tm_year, ts.tm_mon, ts.tm_mday, ts.tm_hour, ts.tm_min, ts.tm_sec, now.tv_nsec, g_logLevelNames[level], file_name, line, formatted_func_name); if (str1_len <= 0) goto end; str2_len = vsnprintf(NULL, 0, fmt, args); @@ -128,7 +133,7 @@ __attribute__((format(printf, 7, 8))) void logWriteFormattedStringToBuffer(char } /* Generate formatted string. */ - sprintf(dst_ptr + dst_str_len, g_logStrFormat, ts.tm_year, ts.tm_mon, ts.tm_mday, ts.tm_hour, ts.tm_min, ts.tm_sec, now.tv_nsec, g_logLevelNames[level], file_name, line, func_name); + sprintf(dst_ptr + dst_str_len, g_logStrFormat, ts.tm_year, ts.tm_mon, ts.tm_mday, ts.tm_hour, ts.tm_min, ts.tm_sec, now.tv_nsec, g_logLevelNames[level], file_name, line, formatted_func_name); vsprintf(dst_ptr + dst_str_len + (size_t)str1_len, fmt, args); strcat(dst_ptr, CRLF); @@ -304,6 +309,9 @@ static void _logWriteFormattedStringToLogFile(bool save, u8 level, const char *f struct tm ts = {0}; struct timespec now = {0}; + char formatted_func_name[0x100] = {0}; + logFormatFunctionName(func_name, formatted_func_name, MAX_ELEMENTS(formatted_func_name)); + /* Get current time with nanosecond precision. */ clock_gettime(CLOCK_REALTIME, &now); @@ -313,7 +321,7 @@ static void _logWriteFormattedStringToLogFile(bool save, u8 level, const char *f ts.tm_mon++; /* Get formatted string length. */ - str1_len = snprintf(NULL, 0, g_logStrFormat, ts.tm_year, ts.tm_mon, ts.tm_mday, ts.tm_hour, ts.tm_min, ts.tm_sec, now.tv_nsec, g_logLevelNames[level], file_name, line, func_name); + str1_len = snprintf(NULL, 0, g_logStrFormat, ts.tm_year, ts.tm_mon, ts.tm_mday, ts.tm_hour, ts.tm_min, ts.tm_sec, now.tv_nsec, g_logLevelNames[level], file_name, line, formatted_func_name); if (str1_len <= 0) return; str2_len = vsnprintf(NULL, 0, fmt, args); @@ -326,12 +334,12 @@ static void _logWriteFormattedStringToLogFile(bool save, u8 level, const char *f { if (g_lastLogMsg) free(g_lastLogMsg); - tmp_len = (strlen(func_name) + 2); + tmp_len = (strlen(formatted_func_name) + 2); g_lastLogMsg = calloc(tmp_len + (size_t)str2_len + 1, sizeof(char)); if (g_lastLogMsg) { - sprintf(g_lastLogMsg, "%s: ", func_name); + sprintf(g_lastLogMsg, "%s: ", formatted_func_name); vsprintf(g_lastLogMsg + tmp_len, fmt, args); } @@ -349,7 +357,7 @@ static void _logWriteFormattedStringToLogFile(bool save, u8 level, const char *f } /* Nice and easy string formatting using the log buffer. */ - sprintf(g_logBuffer + g_logBufferLength, g_logStrFormat, ts.tm_year, ts.tm_mon, ts.tm_mday, ts.tm_hour, ts.tm_min, ts.tm_sec, now.tv_nsec, g_logLevelNames[level], file_name, line, func_name); + sprintf(g_logBuffer + g_logBufferLength, g_logStrFormat, ts.tm_year, ts.tm_mon, ts.tm_mday, ts.tm_hour, ts.tm_min, ts.tm_sec, now.tv_nsec, g_logLevelNames[level], file_name, line, formatted_func_name); vsprintf(g_logBuffer + g_logBufferLength + (size_t)str1_len, fmt, args); strcat(g_logBuffer, CRLF); @@ -368,7 +376,7 @@ static void _logWriteFormattedStringToLogFile(bool save, u8 level, const char *f if (!tmp_str) return; /* Generate formatted string. */ - sprintf(tmp_str, g_logStrFormat, ts.tm_year, ts.tm_mon, ts.tm_mday, ts.tm_hour, ts.tm_min, ts.tm_sec, now.tv_nsec, g_logLevelNames[level], file_name, line, func_name); + sprintf(tmp_str, g_logStrFormat, ts.tm_year, ts.tm_mon, ts.tm_mday, ts.tm_hour, ts.tm_min, ts.tm_sec, now.tv_nsec, g_logLevelNames[level], file_name, line, formatted_func_name); vsprintf(tmp_str + (size_t)str1_len, fmt, args); strcat(tmp_str, CRLF); @@ -493,6 +501,23 @@ static bool logOpenLogFile(void) return R_SUCCEEDED(rc); } +static void logFormatFunctionName(const char *func_name, char *out, size_t out_size) +{ + const char *begin = NULL, *end = NULL; + + end = strchr(func_name, '('); + if (!end) + { + snprintf(out, out_size, "%s", func_name); + return; + } + + begin = memrchr(func_name, ' ', end - func_name); + begin = (begin ? (begin + 1) : func_name); + + snprintf(out, out_size, "%.*s", (int)(end - begin), begin); +} + static void logWriteStringToNxLink(const char *str) { int fd = utilsGetNxLinkFileDescriptor(); diff --git a/source/tasks/gamecard_image_dump_task.cpp b/source/tasks/gamecard_image_dump_task.cpp index 8ad005c..e08520e 100644 --- a/source/tasks/gamecard_image_dump_task.cpp +++ b/source/tasks/gamecard_image_dump_task.cpp @@ -83,6 +83,7 @@ namespace nxdt::tasks try { file = new nxdt::utils::FileWriter(output_path, gc_img_size); } catch(const std::string& msg) { + LOG_MSG_ERROR("%s", msg.c_str()); return msg; } diff --git a/source/utils/file_writer.cpp b/source/utils/file_writer.cpp index e9ddd70..ee04544 100644 --- a/source/utils/file_writer.cpp +++ b/source/utils/file_writer.cpp @@ -28,6 +28,14 @@ namespace nxdt::utils { FileWriter::FileWriter(const std::string& output_path, const size_t& total_size, const u32& nsp_header_size) : output_path(output_path), total_size(total_size), nsp_header_size(nsp_header_size) { + const char *output_path_str = this->output_path.c_str(); + + LOG_MSG_DEBUG("Creating FileWriter object with arguments:\r\n" \ + "- output_path: \"%s\".\r\n" \ + "- total_size: 0x%lX.\r\n" \ + "- nsp_header_size: 0x%X.", \ + output_path_str, total_size, nsp_header_size); + /* Determine the storage device based on the input path. */ this->storage_type = (this->output_path.starts_with(DEVOPTAB_SDMC_DEVICE) ? StorageType::SdCard : (this->output_path.starts_with('/') ? StorageType::UsbHost : StorageType::UmsDevice)); @@ -41,7 +49,7 @@ namespace nxdt::utils } else { /* Get UMS device info. */ UsbHsFsDevice ums_device{}; - if (!usbHsFsGetDeviceByPath(this->output_path.c_str(), &ums_device)) throw "utils/file_writer/ums_device_info_error"_i18n; + if (!usbHsFsGetDeviceByPath(output_path_str, &ums_device)) throw "utils/file_writer/ums_device_info_error"_i18n; /* Determine if we should split the output file based on the UMS device's filesystem type. */ this->split_file = (this->total_size > FAT32_FILESIZE_LIMIT && ums_device.fs_type < UsbHsFsDeviceFileSystemType_exFAT); @@ -51,8 +59,10 @@ namespace nxdt::utils } } + LOG_MSG_DEBUG("storage_type: %d | split_file: %u | split_file_part_cnt: %u", this->storage_type, this->split_file, this->split_file_part_cnt); + /* Check free space. */ - if (auto chk = this->CheckFreeSpace()) throw *chk; + if (auto chk = this->CheckFreeSpace()) throw chk.value(); /* Create initial file. */ if (!this->CreateInitialFile()) @@ -93,8 +103,13 @@ namespace nxdt::utils /* Short-circuit: don't perform any free space check if we're dealing with a USB host or if the file size is zero. */ if (this->storage_type == StorageType::UsbHost || !this->total_size) return {}; + LOG_MSG_DEBUG("Checking free space..."); + /* Retrieve free space from the target storage device. */ - if (!utilsGetFileSystemStatsByPath(this->output_path.c_str(), nullptr, &free_space)) return "utils/file_writer/free_space_check/retrieve_error"_i18n; + const char *output_path_str = this->output_path.c_str(); + if (!utilsGetFileSystemStatsByPath(output_path_str, nullptr, &free_space)) return "utils/file_writer/free_space_check/retrieve_error"_i18n; + + LOG_MSG_DEBUG("Free space in \"%.*s\": 0x%lX.", static_cast(strchr(output_path_str, '/') + 1 - output_path_str), output_path_str, free_space); /* Perform the actual free space check. */ bool ret = (free_space > this->total_size); @@ -112,6 +127,7 @@ namespace nxdt::utils { if (this->fp) { + LOG_MSG_DEBUG("Closing current file."); fclose(this->fp); this->fp = nullptr; } @@ -136,10 +152,13 @@ namespace nxdt::utils if (this->storage_type == StorageType::SdCard || !this->split_file) { /* Open file using the provided output path, but only if we're dealing with the SD card or if we're not dealing with a split file. */ - this->fp = fopen(this->output_path.c_str(), "wb"); + const char *output_path_str = this->output_path.c_str(); + LOG_MSG_DEBUG("Opening output file: \"%s\".", output_path_str); + this->fp = fopen(output_path_str, "wb"); } else { - /* Open current part file. */ + /* Open next part file using our stored part file index. */ std::string part_file_path = fmt::format("{}/{:02d}", this->output_path, this->split_file_part_idx); + LOG_MSG_DEBUG("Opening next part file: \"%s\".", part_file_path.c_str()); this->fp = fopen(part_file_path.c_str(), "wb"); if (this->fp) { @@ -152,7 +171,11 @@ namespace nxdt::utils } /* Return immediately if we couldn't open the file in creation mode. */ - if (!this->fp) return false; + if (!this->fp) + { + LOG_MSG_ERROR("fopen() failed! (%d).", errno); + return false; + } /* Close file and return immediately if we're dealing with an empty file. */ if (!this->file_created && !this->total_size) @@ -164,23 +187,6 @@ namespace nxdt::utils /* Disable file stream buffering. */ setvbuf(this->fp, nullptr, _IONBF, 0); - /* Truncate file to the right size. */ - off_t truncate_size = 0; - - if (this->storage_type == StorageType::SdCard || !this->split_file) - { - truncate_size = static_cast(this->total_size); - } else { - if (this->split_file_part_idx < this->split_file_part_cnt) - { - truncate_size = static_cast(CONCATENATION_FILE_PART_SIZE); - } else { - truncate_size = static_cast(this->total_size - (CONCATENATION_FILE_PART_SIZE * static_cast(this->split_file_part_cnt - 1))); - } - } - - ftruncate(fileno(this->fp), truncate_size); - return true; } @@ -194,27 +200,20 @@ namespace nxdt::utils if (this->storage_type == StorageType::UsbHost) { /* Send file properties to USB host. */ + LOG_MSG_DEBUG("Sending file properties to USB host..."); if ((!this->nsp_header_size && !usbSendFileProperties(this->total_size, output_path_str)) || (this->nsp_header_size && !usbSendNspProperties(this->total_size, output_path_str, this->nsp_header_size))) return false; } else { - /* Check if we're supposed to create a split file. */ - if (this->split_file) - { - if (this->storage_type == StorageType::SdCard) - { - /* Create directory tree. */ - utilsCreateDirectoryTree(output_path_str, false); + /* Create directory tree. */ + /* We'll only create a directory for the last path element if we're dealing with a split file in a FAT-formatted UMS volume. */ + LOG_MSG_DEBUG("Creating directory tree..."); + utilsCreateDirectoryTree(output_path_str, this->split_file && this->storage_type == StorageType::UmsDevice); - /* Create concatenation file on the SD card. */ - if (!utilsCreateConcatenationFile(output_path_str)) return false; - } else { - /* Create directory tree, including the last path element. */ - /* We'll handle split file creation ourselves at a later point. */ - utilsCreateDirectoryTree(output_path_str, true); - } - } else { - /* Create directory tree. */ - utilsCreateDirectoryTree(output_path_str, false); + /* Create concatenation file on the SD card, if needed. */ + if (this->split_file && this->storage_type == StorageType::SdCard) + { + LOG_MSG_DEBUG("Creating concatenation file on the SD card..."); + if (!utilsCreateConcatenationFile(output_path_str)) return false; } /* Open initial file. */ @@ -244,7 +243,13 @@ namespace nxdt::utils size_t part_file_write_size = ((this->split_file_part_size + write_size) > CONCATENATION_FILE_PART_SIZE ? (CONCATENATION_FILE_PART_SIZE - this->split_file_part_size) : write_size); /* Write data to current part file. */ - if (fwrite(data, 1, part_file_write_size, this->fp) != part_file_write_size) return false; + size_t n = fwrite(data, 1, part_file_write_size, this->fp); + if (n != part_file_write_size) + { + LOG_MSG_ERROR("fwrite() failed to write 0x%lX-byte long block at offset 0x%lX to part file #%u (absolute offset 0x%lX).", + part_file_write_size, this->split_file_part_size, this->split_file_part_idx - 1, this->cur_size); + return false; + } /* Update part file size. */ this->split_file_part_size += part_file_write_size; @@ -258,10 +263,19 @@ namespace nxdt::utils if (this->storage_type == StorageType::UsbHost) { /* Send data to USB host. */ - if (!usbSendFileData(data, write_size)) return false; + if (!usbSendFileData(data, write_size)) + { + LOG_MSG_ERROR("Failed to send 0x%lX-byte long block at offset 0x%lX to USB host.", write_size, this->cur_size); + return false; + } } else { /* Write data to output file. */ - if (fwrite(data, 1, write_size, this->fp) != write_size) return false; + size_t n = fwrite(data, 1, write_size, this->fp); + if (n != write_size) + { + LOG_MSG_ERROR("fwrite() failed to write 0x%lX-byte long block at offset 0x%lX to output file.", write_size, this->cur_size); + return false; + } } /* Update the written data size. */ @@ -322,18 +336,22 @@ namespace nxdt::utils { if (this->storage_type == StorageType::UsbHost) { + LOG_MSG_DEBUG("Cancelling USB file transfer..."); usbCancelFileTransfer(); } else { const char *output_path_str = this->output_path.c_str(); if (this->storage_type == StorageType::SdCard) { + LOG_MSG_DEBUG("Removing concatenation file on the SD card..."); utilsRemoveConcatenationFile(output_path_str); } else { if (this->split_file) { + LOG_MSG_DEBUG("Deleting output directory on UMS device..."); utilsDeleteDirectoryRecursively(output_path_str); } else { + LOG_MSG_DEBUG("Removing output file on UMS device..."); remove(output_path_str); } } @@ -341,7 +359,11 @@ namespace nxdt::utils } /* Commit SD card filesystem changes, if needed. */ - if (this->storage_type == StorageType::SdCard) utilsCommitSdCardFileSystemChanges(); + if (this->storage_type == StorageType::SdCard) + { + utilsCommitSdCardFileSystemChanges(); + LOG_MSG_DEBUG("Committed SD card filesystem changes."); + } /* Update flag. */ this->file_closed = true;