Index: common/utils.h =================================================================== --- common/utils.h (revision 13155) +++ common/utils.h (working copy) @@ -28,6 +28,7 @@ #include using std::string; +#include "debuglog.h" #include "str.h" #include @@ -102,6 +103,7 @@ fdcloser(int fd_) : fd(fd_) {} ~fdcloser() { if (fd >= 0) { + IOLOG_CLOSE(1, fd); (void)close(fd); } } Index: common/debuglog.h =================================================================== --- common/debuglog.h (revision 13155) +++ common/debuglog.h (working copy) @@ -417,4 +417,59 @@ #endif +#define XAPIAN_DEBUG_FILEIO 1 +#ifdef XAPIAN_DEBUG_FILEIO + +#include +#include "safeunistd.h" +#include "omtime.h" + +class IoLogger { + const char type; + int fd; + std::string message; + bool is_done; + OmTime start; + public: + // Constructor used for open + IoLogger(const char type_, const char * filename); + IoLogger(const char type_, const std::string & filename); + + // Constructor used for read and write + IoLogger(const char type_, int fd_, off_t offset, int bytes); + + // Constructor used for close / sync + IoLogger(const char type_, int fd_); + + void done(int fd_); + void done(); + ~IoLogger() { done(); } +}; + +#define IOLOG_OPEN(var, filename) \ + IoLogger iolog_##var('o', (filename)) +#define IOLOG_CLOSE(var, fd) \ + IoLogger iolog_##var('c', (fd)) +#define IOLOG_PREAD(var, fd, offset, bytes) \ + IoLogger iolog_##var('r', (fd), (offset), (bytes)) +#define IOLOG_PWRITE(var, fd, offset, bytes) \ + IoLogger iolog_##var('w', (fd), (offset), (bytes)) +#define IOLOG_SYNC(var, fd) \ + IoLogger iolog_##var('s', (fd)) +#define IOLOG_OPENED(var, fd) iolog_##var.done((fd)) +#define IOLOG_DONE(var) iolog_##var.done() + +#else + +#define IOLOG_OPEN(var, filename) +#define IOLOG_CLOSE(var, fd) +#define IOLOG_PREAD(var, fd, offset, bytes) +#define IOLOG_PWRITE(var, fd, offset, bytes) +#define IOLOG_SYNC(var, fd) +#define IOLOG_OPENED(var, fd) +#define IOLOG_DONE(var) + +#endif + + #endif // XAPIAN_INCLUDED_DEBUGLOG_H Index: common/debuglog.cc =================================================================== --- common/debuglog.cc (revision 13155) +++ common/debuglog.cc (working copy) @@ -141,3 +141,143 @@ } #endif // XAPIAN_DEBUG_VERBOSE + +// FIXME - don't need to include this when config is in config.h +#include "debuglog.h" +#ifdef XAPIAN_DEBUG_FILEIO + +#include "debuglog.h" + +#include "str.h" + +#include +#include +#include "safeerrno.h" +#include "safefcntl.h" +#include "safeunistd.h" + +#include // For getenv(). +#include // For strerror(). +#include + + +/// Class which writes the messages from IoLogger to disk +class IoLoggerWriter { + int fd; + public: + IoLoggerWriter() : fd(-1) {} + void init(); + void write(const std::string & message); +}; + +void +IoLoggerWriter::init() +{ + fd = -2; // Stop init() being called again. + const char * f = getenv("XAPIAN_IO_LOG"); + if (f && *f) { + if (f[0] == '-' && f[1] == '\0') { + // Filename "-" means "log to stderr". + fd = 2; + } else { + std::string fnm, pid; + while (*f) { + if (*f == '%' && f[1] == 'p') { + // Replace %p in the filename with the process id. + if (pid.empty()) pid = str(getpid()); + fnm += pid; + f += 2; + } else { + fnm += *f++; + } + } + + fd = open(fnm.c_str(), O_CREAT|O_WRONLY|O_SYNC|O_APPEND, 0644); + if (fd == -1) { + fd = -2; + LOGLINE(ALWAYS, PACKAGE_STRING": Failed to open debug log '" + << fnm << "' (" << strerror(errno) << ')'); + } + } + } +} + +void +IoLoggerWriter::write(const std::string & line) +{ + if (fd == -1) init(); + if (fd < 0) return; + + const char * p = line.data(); + size_t to_do = line.size(); + while (to_do) { + ssize_t n = ::write(fd, p, to_do); + if (n < 0) { + // Retry if interrupted by a signal. + if (errno == EINTR) continue; + + // Upon other errors, close the log file, moan to the debug log, + // and stop logging. + (void)close(fd); + LOGLINE(ALWAYS, PACKAGE_STRING": Failed to write log output (" + << strerror(errno) << ')'); + fd = -2; + return; + } + p += n; + to_do -= n; + } +} + +IoLoggerWriter xapian_iologger__; + +IoLogger::IoLogger(const char type_, const char * filename) + : type(type_), fd(-1), is_done(false), start(OmTime::now()) +{ + message = filename; +} + +IoLogger::IoLogger(const char type_, const std::string & filename) + : type(type_), fd(-1), is_done(false), start(OmTime::now()) +{ + message = filename; +} + +IoLogger::IoLogger(const char type_, int fd_, off_t offset, int bytes) + : type(type_), fd(fd_), is_done(false), start(OmTime::now()) +{ + message = str(offset) + "," + str(bytes); +} + +IoLogger::IoLogger(const char type_, int fd_) + : type(type_), fd(fd_), is_done(false), start(OmTime::now()) +{ +} + +void IoLogger::done() +{ + if (is_done) return; + is_done = true; + + std::string line; + line += type; + line += str(fd); + line += ','; + long long t = start.as_double() * 1000000.0; + line += str(t); + line += ','; + t = ((OmTime::now() - start).as_double()) * 1000000.0; + line += str(t); + line += ','; + line += message; + line += '\n'; + xapian_iologger__.write(line); +} + +void IoLogger::done(int fd_) +{ + fd = fd_; + done(); +} + +#endif // XAPIAN_DEBUG_FILEIO Index: backends/chert/chert_btreebase.cc =================================================================== --- backends/chert/chert_btreebase.cc (revision 13155) +++ backends/chert/chert_btreebase.cc (working copy) @@ -21,6 +21,7 @@ #include +#include "debuglog.h" #include "safeerrno.h" #ifdef __WIN32__ # include "msvc_posix_wrapper.h" @@ -174,11 +175,13 @@ ChertTable_base::read(const string & name, char ch, string &err_msg) { string basename = name + "base" + ch; + IOLOG_OPEN(1, basename); #ifdef __WIN32__ int h = msvc_posix_open(basename.c_str(), O_RDONLY | O_BINARY); #else int h = open(basename.c_str(), O_RDONLY | O_BINARY); #endif + IOLOG_OPENED(1, h); if (h == -1) { err_msg += "Couldn't open " + basename + ": " + strerror(errno) + "\n"; @@ -307,11 +310,13 @@ } buf += pack_uint(revision); // REVISION2 + IOLOG_OPEN(1, filename); #ifdef __WIN32__ int h = msvc_posix_open(filename.c_str(), O_WRONLY | O_CREAT | O_TRUNC | O_BINARY); #else int h = open(filename.c_str(), O_WRONLY | O_CREAT | O_TRUNC | O_BINARY, 0666); #endif + IOLOG_OPENED(1, h); if (h < 0) { string message = string("Couldn't open base ") + filename + " to write: " + strerror(errno); Index: backends/chert/chert_version.cc =================================================================== --- backends/chert/chert_version.cc (revision 13155) +++ backends/chert/chert_version.cc (working copy) @@ -20,6 +20,7 @@ #include +#include "debuglog.h" #include "safeerrno.h" #include @@ -71,7 +72,9 @@ uuid_generate(uuid); memcpy(buf + MAGIC_LEN + 4, (void*)uuid, 16); + IOLOG_OPEN(1, filename); int fd = ::open(filename.c_str(), O_WRONLY|O_CREAT|O_TRUNC|O_BINARY, 0666); + IOLOG_OPENED(1, fd); if (fd < 0) { string msg("Failed to create chert version file: "); @@ -82,21 +85,26 @@ try { chert_io_write(fd, buf, VERSIONFILE_SIZE); } catch (...) { + IOLOG_CLOSE(2, fd); (void)close(fd); throw; } + IOLOG_CLOSE(3, fd); if (close(fd) != 0) { string msg("Failed to create chert version file: "); msg += filename; throw Xapian::DatabaseOpeningError(msg, errno); } + IOLOG_DONE(3); } void ChertVersion::read_and_check() { + IOLOG_OPEN(1, filename); int fd = ::open(filename.c_str(), O_RDONLY|O_BINARY); + IOLOG_OPENED(1, fd); if (fd < 0) { string msg = filename; @@ -110,10 +118,13 @@ try { size = chert_io_read(fd, buf, VERSIONFILE_SIZE + 1, 0); } catch (...) { + IOLOG_CLOSE(2, fd); (void)close(fd); throw; } + IOLOG_CLOSE(3, fd); (void)close(fd); + IOLOG_DONE(3); if (size != VERSIONFILE_SIZE) { CompileTimeAssert(VERSIONFILE_SIZE == VERSIONFILE_SIZE_LITERAL); Index: backends/chert/chert_table.cc =================================================================== --- backends/chert/chert_table.cc (revision 13155) +++ backends/chert/chert_table.cc (working copy) @@ -214,6 +214,7 @@ */ Assert(n / CHAR_BIT < base.get_bit_map_size()); + IOLOG_PREAD(1, handle, off_t(block_size) * n, block_size); #ifdef HAVE_PREAD off_t offset = off_t(block_size) * n; int m = block_size; @@ -277,6 +278,7 @@ latest_revision_number = revision_number; } + IOLOG_PWRITE(1, handle, off_t(block_size) * n, block_size); #ifdef HAVE_PWRITE off_t offset = off_t(block_size) * n; int m = block_size; @@ -1352,7 +1354,9 @@ if (!valid_base) { if (handle >= 0) { + IOLOG_CLOSE(1, handle); ::close(handle); + IOLOG_DONE(1); handle = -1; } string message = "Error opening table `"; @@ -1502,7 +1506,9 @@ } int flags = O_RDWR | O_BINARY; if (create_db) flags |= O_CREAT | O_TRUNC; + IOLOG_OPEN(1, name + "DB"); handle = ::open((name + "DB").c_str(), flags, 0666); + IOLOG_OPENED(1, handle); if (handle < 0) { // lazy doesn't make a lot of sense with create_db anyway, but ENOENT // with O_CREAT means a parent directory doesn't exist. @@ -1518,7 +1524,9 @@ } if (!basic_open(revision_supplied, revision_)) { + IOLOG_CLOSE(2, handle); ::close(handle); + IOLOG_DONE(2); handle = -1; if (!revision_supplied) { throw Xapian::DatabaseOpeningError("Failed to open for writing"); @@ -1769,7 +1777,9 @@ if (handle >= 0) { // If an error occurs here, we just ignore it, since we're just // trying to free everything. + IOLOG_CLOSE(1, handle); (void)::close(handle); + IOLOG_DONE(1); handle = -1; } @@ -1864,11 +1874,16 @@ // Do this as late as possible to allow maximum time for writes to be // committed. + IOLOG_SYNC(1, handle); if (!chert_io_sync(handle)) { + IOLOG_DONE(1); + IOLOG_CLOSE(2, handle); (void)::close(handle); + IOLOG_DONE(2); handle = -1; throw Xapian::DatabaseError("Can't commit new revision - failed to flush DB to disk"); } + IOLOG_DONE(1); // Save to ".tmp" and then rename to "
.base" so // that a reader can't try to read a partially written base file. @@ -2006,7 +2021,9 @@ if (handle == -2) { ChertTable::throw_database_closed(); } + IOLOG_OPEN(1, name + "DB"); handle = ::open((name + "DB").c_str(), O_RDONLY | O_BINARY); + IOLOG_OPENED(1, handle); if (handle < 0) { if (lazy) { // This table is optional when reading! @@ -2021,7 +2038,9 @@ } if (!basic_open(revision_supplied, revision_)) { + IOLOG_CLOSE(2, handle); ::close(handle); + IOLOG_DONE(2); handle = -1; if (revision_supplied) { // The requested revision was not available. Index: backends/flint/flint_version.cc =================================================================== --- backends/flint/flint_version.cc (revision 13155) +++ backends/flint/flint_version.cc (working copy) @@ -20,6 +20,7 @@ #include +#include "debuglog.h" #include "safeerrno.h" #include @@ -68,7 +69,9 @@ v[2] = static_cast((FLINT_VERSION >> 16) & 0xff); v[3] = static_cast((FLINT_VERSION >> 24) & 0xff); + IOLOG_OPEN(1, filename); int fd = ::open(filename.c_str(), O_WRONLY|O_CREAT|O_TRUNC|O_BINARY, 0666); + IOLOG_OPENED(1, fd); if (fd < 0) { string msg("Failed to create flint version file: "); @@ -79,15 +82,18 @@ try { flint_io_write(fd, buf, VERSIONFILE_SIZE); } catch (...) { + IOLOG_CLOSE(2, fd); (void)close(fd); throw; } + IOLOG_CLOSE(3, fd); if (close(fd) != 0) { string msg("Failed to create flint version file: "); msg += filename; throw Xapian::DatabaseOpeningError(msg, errno); } + IOLOG_DONE(3); uuid_clear(uuid); ensure_uuid(); @@ -95,7 +101,9 @@ void FlintVersion::read_and_check(bool readonly) { + IOLOG_OPEN(1, filename); int fd = ::open(filename.c_str(), O_RDONLY|O_BINARY); + IOLOG_OPENED(1, fd); if (fd < 0) { string msg("Failed to open flint version file for reading: "); @@ -109,10 +117,13 @@ try { size = flint_io_read(fd, buf, VERSIONFILE_SIZE + 1, 0); } catch (...) { + IOLOG_CLOSE(2, fd); (void)close(fd); throw; } + IOLOG_CLOSE(3, fd); (void)close(fd); + IOLOG_DONE(3); if (size != VERSIONFILE_SIZE) { string msg("Flint version file "); Index: backends/flint/flint_table.cc =================================================================== --- backends/flint/flint_table.cc (revision 13155) +++ backends/flint/flint_table.cc (working copy) @@ -228,6 +228,7 @@ */ Assert(n / CHAR_BIT < base.get_bit_map_size()); + IOLOG_PREAD(1, handle, off_t(block_size) * n, block_size); #ifdef HAVE_PREAD off_t offset = off_t(block_size) * n; int m = block_size; @@ -291,6 +292,7 @@ latest_revision_number = revision_number; } + IOLOG_PWRITE(1, handle, off_t(block_size) * n, block_size); #ifdef HAVE_PWRITE off_t offset = off_t(block_size) * n; int m = block_size; @@ -1341,7 +1343,9 @@ if (!valid_base) { if (handle >= 0) { + IOLOG_CLOSE(1, handle); ::close(handle); + IOLOG_DONE(1); handle = -1; } string message = "Error opening table `"; @@ -1489,7 +1493,9 @@ } int flags = O_RDWR | O_BINARY; if (create_db) flags |= O_CREAT | O_TRUNC; + IOLOG_OPEN(1, name + "DB"); handle = ::open((name + "DB").c_str(), flags, 0666); + IOLOG_OPENED(1, handle); if (handle < 0) { // lazy doesn't make a lot of sense with create_db anyway, but ENOENT // with O_CREAT means a parent directory doesn't exist. @@ -1505,7 +1511,9 @@ } if (!basic_open(revision_supplied, revision_)) { + IOLOG_CLOSE(2, handle); ::close(handle); + IOLOG_DONE(2); handle = -1; if (!revision_supplied) { throw Xapian::DatabaseOpeningError("Failed to open for writing"); @@ -1756,7 +1764,9 @@ if (handle >= 0) { // If an error occurs here, we just ignore it, since we're just // trying to free everything. + IOLOG_CLOSE(1, handle); (void)::close(handle); + IOLOG_DONE(1); handle = -1; } @@ -1852,11 +1862,16 @@ // Do this as late as possible to allow maximum time for writes to be // committed. + IOLOG_SYNC(1, handle); if (!flint_io_sync(handle)) { + IOLOG_DONE(1); + IOLOG_CLOSE(2, handle); (void)::close(handle); + IOLOG_DONE(2); handle = -1; throw Xapian::DatabaseError("Can't commit new revision - failed to flush DB to disk"); } + IOLOG_DONE(1); // Save to "
.tmp" and then rename to "
.base" so // that a reader can't try to read a partially written base file. @@ -1992,7 +2007,9 @@ if (handle == -2) { FlintTable::throw_database_closed(); } + IOLOG_OPEN(1, name + "DB"); handle = ::open((name + "DB").c_str(), O_RDONLY | O_BINARY); + IOLOG_OPENED(1, handle); if (handle < 0) { if (lazy) { // This table is optional when reading! @@ -2007,7 +2024,9 @@ } if (!basic_open(revision_supplied, revision_)) { + IOLOG_CLOSE(2, handle); ::close(handle); + IOLOG_DONE(2); handle = -1; if (revision_supplied) { // The requested revision was not available. Index: backends/flint/flint_btreebase.cc =================================================================== --- backends/flint/flint_btreebase.cc (revision 13155) +++ backends/flint/flint_btreebase.cc (working copy) @@ -21,6 +21,7 @@ #include +#include "debuglog.h" #include "safeerrno.h" #ifdef __WIN32__ # include "msvc_posix_wrapper.h" @@ -170,11 +171,13 @@ FlintTable_base::read(const string & name, char ch, string &err_msg) { string basename = name + "base" + ch; + IOLOG_OPEN(1, basename); #ifdef __WIN32__ int h = msvc_posix_open(basename.c_str(), O_RDONLY | O_BINARY); #else int h = open(basename.c_str(), O_RDONLY | O_BINARY); #endif + IOLOG_OPENED(1, h); if (h == -1) { err_msg += "Couldn't open " + basename + ": " + strerror(errno) + "\n"; @@ -303,11 +306,13 @@ } buf += F_pack_uint(revision); // REVISION2 + IOLOG_OPEN(1, filename); #ifdef __WIN32__ int h = msvc_posix_open(filename.c_str(), O_WRONLY | O_CREAT | O_TRUNC | O_BINARY); #else int h = open(filename.c_str(), O_WRONLY | O_CREAT | O_TRUNC | O_BINARY, 0666); #endif + IOLOG_OPENED(1, h); if (h < 0) { string message = string("Couldn't open base ") + filename + " to write: " + strerror(errno);