Skip to content

Commit

Permalink
FileWriter: remove call to ftruncate()
Browse files Browse the repository at this point in the history 
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.
  • Loading branch information
@DarkMatterCore
DarkMatterCore committed May 3, 2024
1 parent 7dc0f76 commit 6acdb38
Show file tree
Hide file tree
Showing 4 changed files with 103 additions and 55 deletions.
6 changes: 3 additions & 3 deletions include/core/nxdt_log.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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__)
Expand Down
41 changes: 33 additions & 8 deletions source/core/nxdt_log.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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[] = {
Expand All @@ -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)
Expand Down Expand Up @@ -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;

Expand All @@ -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);
Expand Down Expand Up @@ -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);

Expand Down Expand Up @@ -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);

Expand All @@ -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);
Expand All @@ -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);
}

Expand All @@ -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);

Expand All @@ -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);

Expand Down Expand Up @@ -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();
Expand Down
1 change: 1 addition & 0 deletions source/tasks/gamecard_image_dump_task.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
}

Expand Down
110 changes: 66 additions & 44 deletions source/utils/file_writer.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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));
Expand All @@ -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);
Expand All @@ -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())
Expand Down Expand Up @@ -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<int>(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);
Expand All @@ -112,6 +127,7 @@ namespace nxdt::utils
{
if (this->fp)
{
LOG_MSG_DEBUG("Closing current file.");
fclose(this->fp);
this->fp = nullptr;
}
Expand All @@ -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)
{
Expand All @@ -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)
Expand All @@ -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<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;
}

Expand All @@ -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. */
Expand Down Expand Up @@ -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;
Expand All @@ -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. */
Expand Down Expand Up @@ -322,26 +336,34 @@ 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);
}
}
}
}

/* 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;
Expand Down

0 comments on commit 6acdb38

Please sign in to comment.