Add some basic debug output for log compression
authorJens Axboe <axboe@fb.com>
Wed, 9 Jul 2014 21:01:03 +0000 (23:01 +0200)
committerJens Axboe <axboe@fb.com>
Wed, 9 Jul 2014 21:01:03 +0000 (23:01 +0200)
Guarded by --debug=compress, like the other debug measures.

Signed-off-by: Jens Axboe <axboe@fb.com>
README
debug.h
init.c
iolog.c

diff --git a/README b/README
index 457b83dced1ff21ba90057bf3657b44131d9b76c..e378d3b0cd2a334787ccbeaa47835ab4610eb2c6 100644 (file)
--- a/README
+++ b/README
@@ -210,6 +210,7 @@ Currently, additional logging is available for:
        time            Dump info related to internal time keeping
        net             Dump info related to networking connections
        rate            Dump info related to IO rate switching
        time            Dump info related to internal time keeping
        net             Dump info related to networking connections
        rate            Dump info related to IO rate switching
+       compress        Dump info related to log compress/decompress
        ? or help       Show available debug options.
 
 One can specify multiple debug options: e.g. --debug=file,mem will enable
        ? or help       Show available debug options.
 
 One can specify multiple debug options: e.g. --debug=file,mem will enable
diff --git a/debug.h b/debug.h
index e248695e52b30b803563484ae365c04d9a6f80cc..923fa39958037c3d0aa549e9a6def4b3a9c09756 100644 (file)
--- a/debug.h
+++ b/debug.h
@@ -20,6 +20,7 @@ enum {
        FD_TIME,
        FD_NET,
        FD_RATE,
        FD_TIME,
        FD_NET,
        FD_RATE,
+       FD_COMPRESS,
        FD_DEBUG_MAX,
 };
 
        FD_DEBUG_MAX,
 };
 
diff --git a/init.c b/init.c
index 57aa702471acd65d9a12ec79064204fa1f87f40d..cf1d7f938fb33acfda49b540d94c65249245e070 100644 (file)
--- a/init.c
+++ b/init.c
@@ -1569,7 +1569,7 @@ static void usage(const char *name)
        printf("%s [options] [job options] <job file(s)>\n", name);
        printf("  --debug=options\tEnable debug logging. May be one/more of:\n"
                "\t\t\tprocess,file,io,mem,blktrace,verify,random,parse,\n"
        printf("%s [options] [job options] <job file(s)>\n", name);
        printf("  --debug=options\tEnable debug logging. May be one/more of:\n"
                "\t\t\tprocess,file,io,mem,blktrace,verify,random,parse,\n"
-               "\t\t\tdiskutil,job,mutex,profile,time,net,rate\n");
+               "\t\t\tdiskutil,job,mutex,profile,time,net,rate,compress\n");
        printf("  --parse-only\t\tParse options only, don't start any IO\n");
        printf("  --output\t\tWrite output to file\n");
        printf("  --runtime\t\tRuntime in seconds\n");
        printf("  --parse-only\t\tParse options only, don't start any IO\n");
        printf("  --output\t\tWrite output to file\n");
        printf("  --runtime\t\tRuntime in seconds\n");
@@ -1677,6 +1677,10 @@ struct debug_level debug_levels[] = {
          .help = "Rate logging",
          .shift = FD_RATE,
        },
          .help = "Rate logging",
          .shift = FD_RATE,
        },
+       { .name = "compress",
+         .help = "Log compression logging",
+         .shift = FD_COMPRESS,
+       },
        { .name = NULL, },
 };
 
        { .name = NULL, },
 };
 
diff --git a/iolog.c b/iolog.c
index 79c189b70af83e1e5d452ab08b1bff291222709a..100b5d79eb14001cdbdddda7cc17c337765f0b52 100644 (file)
--- a/iolog.c
+++ b/iolog.c
@@ -735,6 +735,11 @@ static void finish_chunk(z_stream *stream, FILE *f,
 static size_t inflate_chunk(struct iolog_compress *ic, int gz_hdr, FILE *f,
                            z_stream *stream, struct inflate_chunk_iter *iter)
 {
 static size_t inflate_chunk(struct iolog_compress *ic, int gz_hdr, FILE *f,
                            z_stream *stream, struct inflate_chunk_iter *iter)
 {
+       size_t ret;
+
+       dprint(FD_COMPRESS, "inflate chunk size=%lu, seq=%u",
+                               (unsigned long) ic->len, ic->seq);
+
        if (ic->seq != iter->seq) {
                if (iter->seq)
                        finish_chunk(stream, f, iter);
        if (ic->seq != iter->seq) {
                if (iter->seq)
                        finish_chunk(stream, f, iter);
@@ -777,7 +782,11 @@ static size_t inflate_chunk(struct iolog_compress *ic, int gz_hdr, FILE *f,
                        break;
        }
 
                        break;
        }
 
-       return (void *) stream->next_in - ic->buf;
+       ret = (void *) stream->next_in - ic->buf;
+
+       dprint(FD_COMPRESS, "inflated to size=%lu\n", (unsigned long) ret);
+
+       return ret;
 }
 
 /*
 }
 
 /*
@@ -798,6 +807,9 @@ static int inflate_gz_chunks(struct io_log *log, FILE *f)
                if (log->log_gz_store) {
                        size_t ret;
 
                if (log->log_gz_store) {
                        size_t ret;
 
+                       dprint(FD_COMPRESS, "log write chunk size=%lu, "
+                               "seq=%u\n", (unsigned long) ic->len, ic->seq);
+
                        ret = fwrite(ic->buf, ic->len, 1, f);
                        if (ret != 1 || ferror(f)) {
                                iter.err = errno;
                        ret = fwrite(ic->buf, ic->len, 1, f);
                        if (ret != 1 || ferror(f)) {
                                iter.err = errno;
@@ -986,6 +998,8 @@ static int gz_work(struct tp_work *work)
        stream.next_in = (void *) data->samples;
        stream.avail_in = data->nr_samples * log_entry_sz(data->log);
 
        stream.next_in = (void *) data->samples;
        stream.avail_in = data->nr_samples * log_entry_sz(data->log);
 
+       dprint(FD_COMPRESS, "deflate input size=%lu, seq=%u\n",
+                               (unsigned long) stream.avail_in, seq);
        do {
                c = get_new_chunk(seq);
                stream.avail_out = GZ_CHUNK;
        do {
                c = get_new_chunk(seq);
                stream.avail_out = GZ_CHUNK;
@@ -1015,10 +1029,13 @@ static int gz_work(struct tp_work *work)
                        stream.next_out = c->buf;
                        ret = deflate(&stream, Z_FINISH);
                        c->len = GZ_CHUNK - stream.avail_out;
                        stream.next_out = c->buf;
                        ret = deflate(&stream, Z_FINISH);
                        c->len = GZ_CHUNK - stream.avail_out;
+                       total += c->len;
                        flist_add_tail(&c->list, &list);
                } while (ret != Z_STREAM_END);
        }
 
                        flist_add_tail(&c->list, &list);
                } while (ret != Z_STREAM_END);
        }
 
+       dprint(FD_COMPRESS, "deflated to size=%lu\n", (unsigned long) total);
+
        ret = deflateEnd(&stream);
        if (ret != Z_OK)
                log_err("fio: deflateEnd %d\n", ret);
        ret = deflateEnd(&stream);
        if (ret != Z_OK)
                log_err("fio: deflateEnd %d\n", ret);