Ticket #390: patch

File patch, 16.6 KB (added by Richard Boulton, 15 years ago)

Initial patch to implement this logging.

  • common/utils.h

     
    2828#include <string>
    2929using std::string;
    3030
     31#include "debuglog.h"
    3132#include "str.h"
    3233
    3334#include <cstdlib>
    … …  
    102103        fdcloser(int fd_) : fd(fd_) {}
    103104        ~fdcloser() {
    104105            if (fd >= 0) {
     106                IOLOG_CLOSE(1, fd);
    105107                (void)close(fd);
    106108            }
    107109        }

  • common/debuglog.h

     
    417417
    418418#endif
    419419
     420#define XAPIAN_DEBUG_FILEIO 1
     421#ifdef XAPIAN_DEBUG_FILEIO
     422
     423#include <string>
     424#include "safeunistd.h"
     425#include "omtime.h"
     426
     427class IoLogger {
     428    const char type;
     429    int fd;
     430    std::string message;
     431    bool is_done;
     432    OmTime start;
     433  public:
     434    // Constructor used for open
     435    IoLogger(const char type_, const char * filename);
     436    IoLogger(const char type_, const std::string & filename);
     437
     438    // Constructor used for read and write
     439    IoLogger(const char type_, int fd_, off_t offset, int bytes);
     440
     441    // Constructor used for close / sync
     442    IoLogger(const char type_, int fd_);
     443
     444    void done(int fd_);
     445    void done();
     446    ~IoLogger() { done(); }
     447};
     448
     449#define IOLOG_OPEN(var, filename) \
     450        IoLogger iolog_##var('o', (filename))
     451#define IOLOG_CLOSE(var, fd) \
     452        IoLogger iolog_##var('c', (fd))
     453#define IOLOG_PREAD(var, fd, offset, bytes) \
     454        IoLogger iolog_##var('r', (fd), (offset), (bytes))
     455#define IOLOG_PWRITE(var, fd, offset, bytes) \
     456        IoLogger iolog_##var('w', (fd), (offset), (bytes))
     457#define IOLOG_SYNC(var, fd) \
     458        IoLogger iolog_##var('s', (fd))
     459#define IOLOG_OPENED(var, fd) iolog_##var.done((fd))
     460#define IOLOG_DONE(var) iolog_##var.done()
     461
     462#else
     463
     464#define IOLOG_OPEN(var, filename)
     465#define IOLOG_CLOSE(var, fd)
     466#define IOLOG_PREAD(var, fd, offset, bytes)
     467#define IOLOG_PWRITE(var, fd, offset, bytes)
     468#define IOLOG_SYNC(var, fd)
     469#define IOLOG_OPENED(var, fd)
     470#define IOLOG_DONE(var)
     471
     472#endif
     473
     474
    420475#endif // XAPIAN_INCLUDED_DEBUGLOG_H

  • common/debuglog.cc

     
    141141}
    142142
    143143#endif // XAPIAN_DEBUG_VERBOSE
     144
     145// FIXME - don't need to include this when config is in config.h
     146#include "debuglog.h"
     147#ifdef XAPIAN_DEBUG_FILEIO
     148
     149#include "debuglog.h"
     150
     151#include "str.h"
     152
     153#include <sys/types.h>
     154#include <sys/stat.h>
     155#include "safeerrno.h"
     156#include "safefcntl.h"
     157#include "safeunistd.h"
     158
     159#include <cstdlib> // For getenv().
     160#include <cstring> // For strerror().
     161#include <string>
     162
     163
     164/// Class which writes the messages from IoLogger to disk
     165class IoLoggerWriter {
     166    int fd;
     167  public:
     168    IoLoggerWriter() : fd(-1) {}
     169    void init();
     170    void write(const std::string & message);
     171};
     172
     173void
     174IoLoggerWriter::init()
     175{
     176    fd = -2; // Stop init() being called again.
     177    const char * f = getenv("XAPIAN_IO_LOG");
     178    if (f && *f) {
     179        if (f[0] == '-' && f[1] == '\0') {
     180            // Filename "-" means "log to stderr".
     181            fd = 2;
     182        } else {
     183            std::string fnm, pid;
     184            while (*f) {
     185                if (*f == '%' && f[1] == 'p') {
     186                    // Replace %p in the filename with the process id.
     187                    if (pid.empty()) pid = str(getpid());
     188                    fnm += pid;
     189                    f += 2;
     190                } else {
     191                    fnm += *f++;
     192                }
     193            }
     194
     195            fd = open(fnm.c_str(), O_CREAT|O_WRONLY|O_SYNC|O_APPEND, 0644);
     196            if (fd == -1) {
     197                fd = -2;
     198                LOGLINE(ALWAYS, PACKAGE_STRING": Failed to open debug log '"
     199                        << fnm << "' (" << strerror(errno) << ')');
     200            }
     201        }
     202    }
     203}
     204
     205void
     206IoLoggerWriter::write(const std::string & line)
     207{
     208    if (fd == -1) init();
     209    if (fd < 0) return;
     210
     211    const char * p = line.data();
     212    size_t to_do = line.size();
     213    while (to_do) {
     214        ssize_t n = ::write(fd, p, to_do);
     215        if (n < 0) {
     216            // Retry if interrupted by a signal.
     217            if (errno == EINTR) continue;
     218
     219            // Upon other errors, close the log file, moan to the debug log,
     220            // and stop logging.
     221            (void)close(fd);
     222            LOGLINE(ALWAYS, PACKAGE_STRING": Failed to write log output ("
     223                    << strerror(errno) << ')');
     224            fd = -2;
     225            return;
     226        }
     227        p += n;
     228        to_do -= n;
     229    }
     230}
     231
     232IoLoggerWriter xapian_iologger__;
     233
     234IoLogger::IoLogger(const char type_, const char * filename)
     235        : type(type_), fd(-1), is_done(false), start(OmTime::now())
     236{
     237    message = filename;
     238}
     239
     240IoLogger::IoLogger(const char type_, const std::string & filename)
     241        : type(type_), fd(-1), is_done(false), start(OmTime::now())
     242{
     243    message = filename;
     244}
     245
     246IoLogger::IoLogger(const char type_, int fd_, off_t offset, int bytes)
     247        : type(type_), fd(fd_), is_done(false), start(OmTime::now())
     248{
     249    message = str(offset) + "," + str(bytes);
     250}
     251
     252IoLogger::IoLogger(const char type_, int fd_)
     253        : type(type_), fd(fd_), is_done(false), start(OmTime::now())
     254{
     255}
     256
     257void IoLogger::done()
     258{
     259    if (is_done) return;
     260    is_done = true;
     261
     262    std::string line;
     263    line += type;
     264    line += str(fd);
     265    line += ',';
     266    long long t = start.as_double() * 1000000.0;
     267    line += str(t);
     268    line += ',';
     269    t = ((OmTime::now() - start).as_double()) * 1000000.0;
     270    line += str(t);
     271    line += ',';
     272    line += message;
     273    line += '\n';
     274    xapian_iologger__.write(line);
     275}
     276
     277void IoLogger::done(int fd_)
     278{
     279    fd = fd_;
     280    done();
     281}
     282
     283#endif // XAPIAN_DEBUG_FILEIO

  • backends/chert/chert_btreebase.cc

     
    2121
    2222#include <config.h>
    2323
     24#include "debuglog.h"
    2425#include "safeerrno.h"
    2526#ifdef __WIN32__
    2627# include "msvc_posix_wrapper.h"
    … …  
    174175ChertTable_base::read(const string & name, char ch, string &err_msg)
    175176{
    176177    string basename = name + "base" + ch;
     178    IOLOG_OPEN(1, basename);
    177179#ifdef __WIN32__
    178180    int h = msvc_posix_open(basename.c_str(), O_RDONLY | O_BINARY);
    179181#else
    180182    int h = open(basename.c_str(), O_RDONLY | O_BINARY);
    181183#endif
     184    IOLOG_OPENED(1, h);
    182185
    183186    if (h == -1) {
    184187        err_msg += "Couldn't open " + basename + ": " + strerror(errno) + "\n";
    … …  
    307310    }
    308311    buf += pack_uint(revision);  // REVISION2
    309312
     313    IOLOG_OPEN(1, filename);
    310314#ifdef __WIN32__
    311315    int h = msvc_posix_open(filename.c_str(), O_WRONLY | O_CREAT | O_TRUNC | O_BINARY);
    312316#else
    313317    int h = open(filename.c_str(), O_WRONLY | O_CREAT | O_TRUNC | O_BINARY, 0666);
    314318#endif
     319    IOLOG_OPENED(1, h);
    315320    if (h < 0) {
    316321        string message = string("Couldn't open base ")
    317322                + filename + " to write: " + strerror(errno);

  • backends/chert/chert_version.cc

     
    2020
    2121#include <config.h>
    2222
     23#include "debuglog.h"
    2324#include "safeerrno.h"
    2425
    2526#include <xapian/error.h>
    … …  
    7172    uuid_generate(uuid);
    7273    memcpy(buf + MAGIC_LEN + 4, (void*)uuid, 16);
    7374
     75    IOLOG_OPEN(1, filename);
    7476    int fd = ::open(filename.c_str(), O_WRONLY|O_CREAT|O_TRUNC|O_BINARY, 0666);
     77    IOLOG_OPENED(1, fd);
    7578
    7679    if (fd < 0) {
    7780        string msg("Failed to create chert version file: ");
    … …  
    8285    try {
    8386        chert_io_write(fd, buf, VERSIONFILE_SIZE);
    8487    } catch (...) {
     88        IOLOG_CLOSE(2, fd);
    8589        (void)close(fd);
    8690        throw;
    8791    }
    8892
     93    IOLOG_CLOSE(3, fd);
    8994    if (close(fd) != 0) {
    9095        string msg("Failed to create chert version file: ");
    9196        msg += filename;
    9297        throw Xapian::DatabaseOpeningError(msg, errno);
    9398    }
     99    IOLOG_DONE(3);
    94100}
    95101
    96102void
    97103ChertVersion::read_and_check()
    98104{
     105    IOLOG_OPEN(1, filename);
    99106    int fd = ::open(filename.c_str(), O_RDONLY|O_BINARY);
     107    IOLOG_OPENED(1, fd);
    100108
    101109    if (fd < 0) {
    102110        string msg = filename;
    … …  
    110118    try {
    111119        size = chert_io_read(fd, buf, VERSIONFILE_SIZE + 1, 0);
    112120    } catch (...) {
     121        IOLOG_CLOSE(2, fd);
    113122        (void)close(fd);
    114123        throw;
    115124    }
     125    IOLOG_CLOSE(3, fd);
    116126    (void)close(fd);
     127    IOLOG_DONE(3);
    117128
    118129    if (size != VERSIONFILE_SIZE) {
    119130        CompileTimeAssert(VERSIONFILE_SIZE == VERSIONFILE_SIZE_LITERAL);

  • backends/chert/chert_table.cc

     
    214214     */
    215215    Assert(n / CHAR_BIT < base.get_bit_map_size());
    216216
     217    IOLOG_PREAD(1, handle, off_t(block_size) * n, block_size);
    217218#ifdef HAVE_PREAD
    218219    off_t offset = off_t(block_size) * n;
    219220    int m = block_size;
    … …  
    277278        latest_revision_number = revision_number;
    278279    }
    279280
     281    IOLOG_PWRITE(1, handle, off_t(block_size) * n, block_size);
    280282#ifdef HAVE_PWRITE
    281283    off_t offset = off_t(block_size) * n;
    282284    int m = block_size;
    … …  
    13521354
    13531355        if (!valid_base) {
    13541356            if (handle >= 0) {
     1357                IOLOG_CLOSE(1, handle);
    13551358                ::close(handle);
     1359                IOLOG_DONE(1);
    13561360                handle = -1;
    13571361            }
    13581362            string message = "Error opening table `";
    … …  
    15021506    }
    15031507    int flags = O_RDWR | O_BINARY;
    15041508    if (create_db) flags |= O_CREAT | O_TRUNC;
     1509    IOLOG_OPEN(1, name + "DB");
    15051510    handle = ::open((name + "DB").c_str(), flags, 0666);
     1511    IOLOG_OPENED(1, handle);
    15061512    if (handle < 0) {
    15071513        // lazy doesn't make a lot of sense with create_db anyway, but ENOENT
    15081514        // with O_CREAT means a parent directory doesn't exist.
    … …  
    15181524    }
    15191525
    15201526    if (!basic_open(revision_supplied, revision_)) {
     1527        IOLOG_CLOSE(2, handle);
    15211528        ::close(handle);
     1529        IOLOG_DONE(2);
    15221530        handle = -1;
    15231531        if (!revision_supplied) {
    15241532            throw Xapian::DatabaseOpeningError("Failed to open for writing");
    … …  
    17691777    if (handle >= 0) {
    17701778        // If an error occurs here, we just ignore it, since we're just
    17711779        // trying to free everything.
     1780        IOLOG_CLOSE(1, handle);
    17721781        (void)::close(handle);
     1782        IOLOG_DONE(1);
    17731783        handle = -1;
    17741784    }
    17751785
    … …  
    18641874
    18651875        // Do this as late as possible to allow maximum time for writes to be
    18661876        // committed.
     1877        IOLOG_SYNC(1, handle);
    18671878        if (!chert_io_sync(handle)) {
     1879            IOLOG_DONE(1);
     1880            IOLOG_CLOSE(2, handle);
    18681881            (void)::close(handle);
     1882            IOLOG_DONE(2);
    18691883            handle = -1;
    18701884            throw Xapian::DatabaseError("Can't commit new revision - failed to flush DB to disk");
    18711885        }
     1886        IOLOG_DONE(1);
    18721887
    18731888        // Save to "<table>.tmp" and then rename to "<table>.base<letter>" so
    18741889        // that a reader can't try to read a partially written base file.
    … …  
    20062021    if (handle == -2) {
    20072022        ChertTable::throw_database_closed();
    20082023    }
     2024    IOLOG_OPEN(1, name + "DB");
    20092025    handle = ::open((name + "DB").c_str(), O_RDONLY | O_BINARY);
     2026    IOLOG_OPENED(1, handle);
    20102027    if (handle < 0) {
    20112028        if (lazy) {
    20122029            // This table is optional when reading!
    … …  
    20212038    }
    20222039
    20232040    if (!basic_open(revision_supplied, revision_)) {
     2041        IOLOG_CLOSE(2, handle);
    20242042        ::close(handle);
     2043        IOLOG_DONE(2);
    20252044        handle = -1;
    20262045        if (revision_supplied) {
    20272046            // The requested revision was not available.

  • backends/flint/flint_version.cc

     
    2020
    2121#include <config.h>
    2222
     23#include "debuglog.h"
    2324#include "safeerrno.h"
    2425
    2526#include <xapian/error.h>
    … …  
    6869    v[2] = static_cast<unsigned char>((FLINT_VERSION >> 16) & 0xff);
    6970    v[3] = static_cast<unsigned char>((FLINT_VERSION >> 24) & 0xff);
    7071
     72    IOLOG_OPEN(1, filename);
    7173    int fd = ::open(filename.c_str(), O_WRONLY|O_CREAT|O_TRUNC|O_BINARY, 0666);
     74    IOLOG_OPENED(1, fd);
    7275
    7376    if (fd < 0) {
    7477        string msg("Failed to create flint version file: ");
    … …  
    7982    try {
    8083        flint_io_write(fd, buf, VERSIONFILE_SIZE);
    8184    } catch (...) {
     85        IOLOG_CLOSE(2, fd);
    8286        (void)close(fd);
    8387        throw;
    8488    }
    8589
     90    IOLOG_CLOSE(3, fd);
    8691    if (close(fd) != 0) {
    8792        string msg("Failed to create flint version file: ");
    8893        msg += filename;
    8994        throw Xapian::DatabaseOpeningError(msg, errno);
    9095    }
     96    IOLOG_DONE(3);
    9197
    9298    uuid_clear(uuid);
    9399    ensure_uuid();
    … …  
    95101
    96102void FlintVersion::read_and_check(bool readonly)
    97103{
     104    IOLOG_OPEN(1, filename);
    98105    int fd = ::open(filename.c_str(), O_RDONLY|O_BINARY);
     106    IOLOG_OPENED(1, fd);
    99107
    100108    if (fd < 0) {
    101109        string msg("Failed to open flint version file for reading: ");
    … …  
    109117    try {
    110118        size = flint_io_read(fd, buf, VERSIONFILE_SIZE + 1, 0);
    111119    } catch (...) {
     120        IOLOG_CLOSE(2, fd);
    112121        (void)close(fd);
    113122        throw;
    114123    }
     124    IOLOG_CLOSE(3, fd);
    115125    (void)close(fd);
     126    IOLOG_DONE(3);
    116127
    117128    if (size != VERSIONFILE_SIZE) {
    118129        string msg("Flint version file ");

  • backends/flint/flint_table.cc

     
    228228     */
    229229    Assert(n / CHAR_BIT < base.get_bit_map_size());
    230230
     231    IOLOG_PREAD(1, handle, off_t(block_size) * n, block_size);
    231232#ifdef HAVE_PREAD
    232233    off_t offset = off_t(block_size) * n;
    233234    int m = block_size;
    … …  
    291292        latest_revision_number = revision_number;
    292293    }
    293294
     295    IOLOG_PWRITE(1, handle, off_t(block_size) * n, block_size);
    294296#ifdef HAVE_PWRITE
    295297    off_t offset = off_t(block_size) * n;
    296298    int m = block_size;
    … …  
    13411343
    13421344        if (!valid_base) {
    13431345            if (handle >= 0) {
     1346                IOLOG_CLOSE(1, handle);
    13441347                ::close(handle);
     1348                IOLOG_DONE(1);
    13451349                handle = -1;
    13461350            }
    13471351            string message = "Error opening table `";
    … …  
    14891493    }
    14901494    int flags = O_RDWR | O_BINARY;
    14911495    if (create_db) flags |= O_CREAT | O_TRUNC;
     1496    IOLOG_OPEN(1, name + "DB");
    14921497    handle = ::open((name + "DB").c_str(), flags, 0666);
     1498    IOLOG_OPENED(1, handle);
    14931499    if (handle < 0) {
    14941500        // lazy doesn't make a lot of sense with create_db anyway, but ENOENT
    14951501        // with O_CREAT means a parent directory doesn't exist.
    … …  
    15051511    }
    15061512
    15071513    if (!basic_open(revision_supplied, revision_)) {
     1514        IOLOG_CLOSE(2, handle);
    15081515        ::close(handle);
     1516        IOLOG_DONE(2);
    15091517        handle = -1;
    15101518        if (!revision_supplied) {
    15111519            throw Xapian::DatabaseOpeningError("Failed to open for writing");
    … …  
    17561764    if (handle >= 0) {
    17571765        // If an error occurs here, we just ignore it, since we're just
    17581766        // trying to free everything.
     1767        IOLOG_CLOSE(1, handle);
    17591768        (void)::close(handle);
     1769        IOLOG_DONE(1);
    17601770        handle = -1;
    17611771    }
    17621772
    … …  
    18521862
    18531863        // Do this as late as possible to allow maximum time for writes to be
    18541864        // committed.
     1865        IOLOG_SYNC(1, handle);
    18551866        if (!flint_io_sync(handle)) {
     1867            IOLOG_DONE(1);
     1868            IOLOG_CLOSE(2, handle);
    18561869            (void)::close(handle);
     1870            IOLOG_DONE(2);
    18571871            handle = -1;
    18581872            throw Xapian::DatabaseError("Can't commit new revision - failed to flush DB to disk");
    18591873        }
     1874        IOLOG_DONE(1);
    18601875
    18611876        // Save to "<table>.tmp" and then rename to "<table>.base<letter>" so
    18621877        // that a reader can't try to read a partially written base file.
    … …  
    19922007    if (handle == -2) {
    19932008        FlintTable::throw_database_closed();
    19942009    }
     2010    IOLOG_OPEN(1, name + "DB");
    19952011    handle = ::open((name + "DB").c_str(), O_RDONLY | O_BINARY);
     2012    IOLOG_OPENED(1, handle);
    19962013    if (handle < 0) {
    19972014        if (lazy) {
    19982015            // This table is optional when reading!
    … …  
    20072024    }
    20082025
    20092026    if (!basic_open(revision_supplied, revision_)) {
     2027        IOLOG_CLOSE(2, handle);
    20102028        ::close(handle);
     2029        IOLOG_DONE(2);
    20112030        handle = -1;
    20122031        if (revision_supplied) {
    20132032            // The requested revision was not available.

  • backends/flint/flint_btreebase.cc

     
    2121
    2222#include <config.h>
    2323
     24#include "debuglog.h"
    2425#include "safeerrno.h"
    2526#ifdef __WIN32__
    2627# include "msvc_posix_wrapper.h"
    … …  
    170171FlintTable_base::read(const string & name, char ch, string &err_msg)
    171172{
    172173    string basename = name + "base" + ch;
     174    IOLOG_OPEN(1, basename);
    173175#ifdef __WIN32__
    174176    int h = msvc_posix_open(basename.c_str(), O_RDONLY | O_BINARY);
    175177#else
    176178    int h = open(basename.c_str(), O_RDONLY | O_BINARY);
    177179#endif
     180    IOLOG_OPENED(1, h);
    178181
    179182    if (h == -1) {
    180183        err_msg += "Couldn't open " + basename + ": " + strerror(errno) + "\n";
    … …  
    303306    }
    304307    buf += F_pack_uint(revision);  // REVISION2
    305308
     309    IOLOG_OPEN(1, filename);
    306310#ifdef __WIN32__
    307311    int h = msvc_posix_open(filename.c_str(), O_WRONLY | O_CREAT | O_TRUNC | O_BINARY);
    308312#else
    309313    int h = open(filename.c_str(), O_WRONLY | O_CREAT | O_TRUNC | O_BINARY, 0666);
    310314#endif
     315    IOLOG_OPENED(1, h);
    311316    if (h < 0) {
    312317        string message = string("Couldn't open base ")
    313318                + filename + " to write: " + strerror(errno);