1
0
Fork 0
mirror of https://github.com/DarkMatterCore/nxdumptool.git synced 2024-11-08 11:51:48 +00:00

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.
This commit is contained in:
Pablo Curiel 2024-05-03 15:14:32 +02:00
parent 7dc0f76224
commit 6acdb38d11
4 changed files with 103 additions and 55 deletions

View file

@ -44,9 +44,9 @@ extern "C" {
/// Helper macros. /// Helper macros.
#define LOG_MSG_GENERIC(level, fmt, ...) logWriteFormattedStringToLogFile(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__, __func__, 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__, __func__, 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 #if LOG_LEVEL == LOG_LEVEL_DEBUG
#define LOG_MSG_DEBUG(fmt, ...) LOG_MSG_GENERIC(LOG_LEVEL_DEBUG, fmt, ##__VA_ARGS__) #define LOG_MSG_DEBUG(fmt, ...) LOG_MSG_GENERIC(LOG_LEVEL_DEBUG, fmt, ##__VA_ARGS__)

View file

@ -35,7 +35,7 @@ static s64 g_logFileOffset = 0;
static char *g_logBuffer = NULL; static char *g_logBuffer = NULL;
static size_t g_logBufferLength = 0; 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_logSessionSeparator = "________________________________________________________________\r\n";
static const char *g_logLevelNames[] = { static const char *g_logLevelNames[] = {
@ -55,6 +55,8 @@ static void _logFlushLogFile(void);
static bool logAllocateLogBuffer(void); static bool logAllocateLogBuffer(void);
static bool logOpenLogFile(void); static bool logOpenLogFile(void);
static void logFormatFunctionName(const char *func_name, char *out, size_t out_size);
static void logWriteStringToNxLink(const char *str); static void logWriteStringToNxLink(const char *str);
void logWriteStringToLogFile(const char *src) void logWriteStringToLogFile(const char *src)
@ -85,6 +87,9 @@ __attribute__((format(printf, 7, 8))) void logWriteFormattedStringToBuffer(char
struct tm ts = {0}; struct tm ts = {0};
struct timespec now = {0}; struct timespec now = {0};
char formatted_func_name[0x100] = {0};
logFormatFunctionName(func_name, formatted_func_name, MAX_ELEMENTS(formatted_func_name));
/* Sanity check. */ /* Sanity check. */
if (dst_cur_size && dst_str_len >= dst_cur_size) return; 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++; ts.tm_mon++;
/* Get formatted string length. */ /* 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; if (str1_len <= 0) goto end;
str2_len = vsnprintf(NULL, 0, fmt, args); str2_len = vsnprintf(NULL, 0, fmt, args);
@ -128,7 +133,7 @@ __attribute__((format(printf, 7, 8))) void logWriteFormattedStringToBuffer(char
} }
/* Generate formatted string. */ /* 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); vsprintf(dst_ptr + dst_str_len + (size_t)str1_len, fmt, args);
strcat(dst_ptr, CRLF); strcat(dst_ptr, CRLF);
@ -304,6 +309,9 @@ static void _logWriteFormattedStringToLogFile(bool save, u8 level, const char *f
struct tm ts = {0}; struct tm ts = {0};
struct timespec now = {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. */ /* Get current time with nanosecond precision. */
clock_gettime(CLOCK_REALTIME, &now); clock_gettime(CLOCK_REALTIME, &now);
@ -313,7 +321,7 @@ static void _logWriteFormattedStringToLogFile(bool save, u8 level, const char *f
ts.tm_mon++; ts.tm_mon++;
/* Get formatted string length. */ /* 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; if (str1_len <= 0) return;
str2_len = vsnprintf(NULL, 0, fmt, args); 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); 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)); g_lastLogMsg = calloc(tmp_len + (size_t)str2_len + 1, sizeof(char));
if (g_lastLogMsg) if (g_lastLogMsg)
{ {
sprintf(g_lastLogMsg, "%s: ", func_name); sprintf(g_lastLogMsg, "%s: ", formatted_func_name);
vsprintf(g_lastLogMsg + tmp_len, fmt, args); 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. */ /* 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); vsprintf(g_logBuffer + g_logBufferLength + (size_t)str1_len, fmt, args);
strcat(g_logBuffer, CRLF); strcat(g_logBuffer, CRLF);
@ -368,7 +376,7 @@ static void _logWriteFormattedStringToLogFile(bool save, u8 level, const char *f
if (!tmp_str) return; if (!tmp_str) return;
/* Generate formatted string. */ /* 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); vsprintf(tmp_str + (size_t)str1_len, fmt, args);
strcat(tmp_str, CRLF); strcat(tmp_str, CRLF);
@ -493,6 +501,23 @@ static bool logOpenLogFile(void)
return R_SUCCEEDED(rc); 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) static void logWriteStringToNxLink(const char *str)
{ {
int fd = utilsGetNxLinkFileDescriptor(); int fd = utilsGetNxLinkFileDescriptor();

View file

@ -83,6 +83,7 @@ namespace nxdt::tasks
try { try {
file = new nxdt::utils::FileWriter(output_path, gc_img_size); file = new nxdt::utils::FileWriter(output_path, gc_img_size);
} catch(const std::string& msg) { } catch(const std::string& msg) {
LOG_MSG_ERROR("%s", msg.c_str());
return msg; return msg;
} }

View file

@ -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) 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. */ /* Determine the storage device based on the input path. */
this->storage_type = (this->output_path.starts_with(DEVOPTAB_SDMC_DEVICE) ? StorageType::SdCard : this->storage_type = (this->output_path.starts_with(DEVOPTAB_SDMC_DEVICE) ? StorageType::SdCard :
(this->output_path.starts_with('/') ? StorageType::UsbHost : StorageType::UmsDevice)); (this->output_path.starts_with('/') ? StorageType::UsbHost : StorageType::UmsDevice));
@ -41,7 +49,7 @@ namespace nxdt::utils
} else { } else {
/* Get UMS device info. */ /* Get UMS device info. */
UsbHsFsDevice ums_device{}; 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. */ /* 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); 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. */ /* Check free space. */
if (auto chk = this->CheckFreeSpace()) throw *chk; if (auto chk = this->CheckFreeSpace()) throw chk.value();
/* Create initial file. */ /* Create initial file. */
if (!this->CreateInitialFile()) 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. */ /* 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 {}; if (this->storage_type == StorageType::UsbHost || !this->total_size) return {};
LOG_MSG_DEBUG("Checking free space...");
/* Retrieve free space from the target storage device. */ /* 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<int>(strchr(output_path_str, '/') + 1 - output_path_str), output_path_str, free_space);
/* Perform the actual free space check. */ /* Perform the actual free space check. */
bool ret = (free_space > this->total_size); bool ret = (free_space > this->total_size);
@ -112,6 +127,7 @@ namespace nxdt::utils
{ {
if (this->fp) if (this->fp)
{ {
LOG_MSG_DEBUG("Closing current file.");
fclose(this->fp); fclose(this->fp);
this->fp = nullptr; this->fp = nullptr;
} }
@ -136,10 +152,13 @@ namespace nxdt::utils
if (this->storage_type == StorageType::SdCard || !this->split_file) 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. */ /* 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 { } 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); 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"); this->fp = fopen(part_file_path.c_str(), "wb");
if (this->fp) if (this->fp)
{ {
@ -152,7 +171,11 @@ namespace nxdt::utils
} }
/* Return immediately if we couldn't open the file in creation mode. */ /* 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. */ /* Close file and return immediately if we're dealing with an empty file. */
if (!this->file_created && !this->total_size) if (!this->file_created && !this->total_size)
@ -164,23 +187,6 @@ namespace nxdt::utils
/* Disable file stream buffering. */ /* Disable file stream buffering. */
setvbuf(this->fp, nullptr, _IONBF, 0); 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<off_t>(this->total_size);
} else {
if (this->split_file_part_idx < this->split_file_part_cnt)
{
truncate_size = static_cast<off_t>(CONCATENATION_FILE_PART_SIZE);
} else {
truncate_size = static_cast<off_t>(this->total_size - (CONCATENATION_FILE_PART_SIZE * static_cast<u64>(this->split_file_part_cnt - 1)));
}
}
ftruncate(fileno(this->fp), truncate_size);
return true; return true;
} }
@ -194,27 +200,20 @@ namespace nxdt::utils
if (this->storage_type == StorageType::UsbHost) if (this->storage_type == StorageType::UsbHost)
{ {
/* Send file properties to USB host. */ /* 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)) || 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; (this->nsp_header_size && !usbSendNspProperties(this->total_size, output_path_str, this->nsp_header_size))) return false;
} else { } else {
/* Check if we're supposed to create a split file. */ /* Create directory tree. */
if (this->split_file) /* 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...");
if (this->storage_type == StorageType::SdCard) utilsCreateDirectoryTree(output_path_str, this->split_file && this->storage_type == StorageType::UmsDevice);
{
/* Create directory tree. */
utilsCreateDirectoryTree(output_path_str, false);
/* Create concatenation file on the SD card. */ /* Create concatenation file on the SD card, if needed. */
if (!utilsCreateConcatenationFile(output_path_str)) return false; if (this->split_file && this->storage_type == StorageType::SdCard)
} else { {
/* Create directory tree, including the last path element. */ LOG_MSG_DEBUG("Creating concatenation file on the SD card...");
/* We'll handle split file creation ourselves at a later point. */ if (!utilsCreateConcatenationFile(output_path_str)) return false;
utilsCreateDirectoryTree(output_path_str, true);
}
} else {
/* Create directory tree. */
utilsCreateDirectoryTree(output_path_str, false);
} }
/* Open initial file. */ /* 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); 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. */ /* 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. */ /* Update part file size. */
this->split_file_part_size += part_file_write_size; this->split_file_part_size += part_file_write_size;
@ -258,10 +263,19 @@ namespace nxdt::utils
if (this->storage_type == StorageType::UsbHost) if (this->storage_type == StorageType::UsbHost)
{ {
/* Send data to USB host. */ /* 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 { } else {
/* Write data to output file. */ /* 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. */ /* Update the written data size. */
@ -322,18 +336,22 @@ namespace nxdt::utils
{ {
if (this->storage_type == StorageType::UsbHost) if (this->storage_type == StorageType::UsbHost)
{ {
LOG_MSG_DEBUG("Cancelling USB file transfer...");
usbCancelFileTransfer(); usbCancelFileTransfer();
} else { } else {
const char *output_path_str = this->output_path.c_str(); const char *output_path_str = this->output_path.c_str();
if (this->storage_type == StorageType::SdCard) if (this->storage_type == StorageType::SdCard)
{ {
LOG_MSG_DEBUG("Removing concatenation file on the SD card...");
utilsRemoveConcatenationFile(output_path_str); utilsRemoveConcatenationFile(output_path_str);
} else { } else {
if (this->split_file) if (this->split_file)
{ {
LOG_MSG_DEBUG("Deleting output directory on UMS device...");
utilsDeleteDirectoryRecursively(output_path_str); utilsDeleteDirectoryRecursively(output_path_str);
} else { } else {
LOG_MSG_DEBUG("Removing output file on UMS device...");
remove(output_path_str); remove(output_path_str);
} }
} }
@ -341,7 +359,11 @@ namespace nxdt::utils
} }
/* Commit SD card filesystem changes, if needed. */ /* 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. */ /* Update flag. */
this->file_closed = true; this->file_closed = true;