Whamcloud - gitweb
Reverted #974 for now as it causes problems for people.
[fs/lustre-release.git] / lustre / tests / fsx.c
index 717b8d4..8524c91 100644 (file)
@@ -127,7 +127,6 @@ int         mapped_reads = 1;               /* -R flag disables it */
 int    fsxgoodfd = 0;
 FILE * fsxlogf = NULL;
 int badoff = -1;
-int closeopen = 0;
 
 
 void
@@ -182,8 +181,6 @@ log4(int operation, int arg0, int arg1, int arg2, struct timeval *tv)
        le = &oplog[logptr];
        le->tv = *tv;
        le->operation = operation;
-       if (closeopen)
-               le->operation = ~ le->operation;
        le->args[0] = arg0;
        le->args[1] = arg1;
        le->args[2] = arg2;
@@ -213,14 +210,12 @@ logdump(void)
 
                opnum = i+1 + (logcount/LOGSIZE)*LOGSIZE;
                lp = &oplog[i];
-               prt("%d(%d mod 256): %lu.%lu ", opnum, opnum%256,
+               prt("%d: %lu.%06lu ", opnum,
                    lp->tv.tv_sec, lp->tv.tv_usec);
-               if ((closeopen = lp->operation < 0))
-                       lp->operation = ~ lp->operation;
 
                switch (lp->operation) {
                case OP_MAPREAD:
-                       prt("MAPREAD\t0x%x thru 0x%x\t(0x%x bytes)",
+                       prt("MAPREAD  0x%x thru 0x%x (0x%x bytes)",
                            lp->args[0], lp->args[0] + lp->args[1] - 1,
                            lp->args[1]);
                        if (badoff >= lp->args[0] && badoff <
@@ -228,7 +223,7 @@ logdump(void)
                                prt("\t***RRRR***");
                        break;
                case OP_MAPWRITE:
-                       prt("MAPWRITE 0x%x thru 0x%x\t(0x%x bytes)",
+                       prt("MAPWRITE 0x%x thru 0x%x (0x%x bytes)",
                            lp->args[0], lp->args[0] + lp->args[1] - 1,
                            lp->args[1]);
                        if (badoff >= lp->args[0] && badoff <
@@ -236,7 +231,7 @@ logdump(void)
                                prt("\t******WWWW");
                        break;
                case OP_READ:
-                       prt("READ\t0x%x thru 0x%x\t(0x%x bytes)",
+                       prt("READ     0x%x thru 0x%x (0x%x bytes)",
                            lp->args[0], lp->args[0] + lp->args[1] - 1,
                            lp->args[1]);
                        if (badoff >= lp->args[0] &&
@@ -244,7 +239,7 @@ logdump(void)
                                prt("\t***RRRR***");
                        break;
                case OP_WRITE:
-                       prt("WRITE\t0x%x thru 0x%x\t(0x%x bytes)",
+                       prt("WRITE    0x%x thru 0x%x (0x%x bytes)",
                            lp->args[0], lp->args[0] + lp->args[1] - 1,
                            lp->args[1]);
                        if (lp->args[0] > lp->args[2])
@@ -263,6 +258,9 @@ logdump(void)
                            badoff < lp->args[!!down])
                                prt("\t******WWWW");
                        break;
+               case OP_CLOSEOPEN:
+                       prt("CLOSE/OPEN");
+                       break;
                case OP_SKIPPED:
                        prt("SKIPPED (no operation)");
                        break;
@@ -270,8 +268,6 @@ logdump(void)
                        prt("BOGUS LOG ENTRY (operation code = %d)!",
                            lp->operation);
                }
-               if (closeopen)
-                       prt("\n\t\tCLOSE/OPEN");
                prt("\n");
                i++;
                if (i == LOGSIZE)
@@ -298,9 +294,10 @@ save_buffer(char *buffer, off_t bufferlength, int fd)
                if (size_by_seek == (off_t)-1)
                        prterr("save_buffer: lseek eof");
                else if (bufferlength > size_by_seek) {
-                       warn("save_buffer: .fsxgood file too short... will
-save 0x%llx bytes instead of 0x%llx\n", (unsigned long long)size_by_seek,
-                            (unsigned long long)bufferlength);
+                       warn("save_buffer: .fsxgood file too short... will"
+                               "save 0x%llx bytes instead of 0x%llx\n", 
+                               (unsigned long long)size_by_seek,
+                               (unsigned long long)bufferlength);
                        bufferlength = size_by_seek;
                }
        }
@@ -314,8 +311,8 @@ save 0x%llx bytes instead of 0x%llx\n", (unsigned long long)size_by_seek,
                if (byteswritten == -1)
                        prterr("save_buffer write");
                else
-                       warn("save_buffer: short write, 0x%x bytes instead
-of 0x%llx\n",
+                       warn("save_buffer: short write, 0x%x bytes instead"
+                               "of 0x%llx\n",
                             (unsigned)byteswritten,
                             (unsigned long long)bufferlength);
        }
@@ -376,11 +373,11 @@ check_buffers(unsigned offset, unsigned size)
                if (n) {
                        prt("\t0x%5x\n", n);
                        if (bad)
-                               prt("operation# (mod 256) for the bad data
-may be %u\n", ((unsigned)op & 0xff));
+                               prt("operation# (mod 256) for the bad data"
+                                       "may be %u\n", ((unsigned)op & 0xff));
                        else
-                               prt("operation# (mod 256) for the bad data
-unknown, check HOLE and EXTEND ops\n");
+                               prt("operation# (mod 256) for the bad data"
+                                       "unknown, check HOLE and EXTEND ops\n");
                } else
                        prt("????????????????\n");
                report_failure(110);
@@ -458,7 +455,7 @@ doread(unsigned offset, unsigned size)
                        (monitorstart == -1 ||
                         (offset + size > monitorstart &&
                          (monitorend == -1 || offset <= monitorend))))))
-               prt("%lu %lu.%lu read\t0x%x thru\t0x%x\t(0x%x bytes)\n",
+               prt("%06lu %lu.%06lu read       %#08x thru %#08x\t(0x%x bytes)\n",
                    testcalls, t.tv_sec, t.tv_usec, offset, offset + size - 1,
                    size);
        ret = lseek(fd, (off_t)offset, SEEK_SET);
@@ -467,6 +464,13 @@ doread(unsigned offset, unsigned size)
                report_failure(140);
        }
        iret = read(fd, temp_buf, size);
+       if (!quiet && (debug > 1 &&
+                       (monitorstart == -1 ||
+                        (offset + size > monitorstart &&
+                         (monitorend == -1 || offset <= monitorend))))) {
+               gettimeofday(&t, NULL);
+               prt("       %lu.%06lu read done\n", t.tv_sec, t.tv_usec);
+       }
        if (iret != size) {
                if (iret == -1)
                        prterr("doread: read");
@@ -513,23 +517,44 @@ domapread(unsigned offset, unsigned size)
                        (monitorstart == -1 ||
                         (offset + size > monitorstart &&
                          (monitorend == -1 || offset <= monitorend))))))
-               prt("%lu %lu.%lu mapread\t0x%x thru\t0x%x\t(0x%x bytes)\n",
+               prt("%06lu %lu.%06lu mapread    %#08x thru %#08x\t(0x%x bytes)\n",
                    testcalls, t.tv_sec, t.tv_usec, offset, offset + size - 1,
                    size);
 
        pg_offset = offset & page_mask;
        map_size  = pg_offset + size;
 
-       if ((p = (char *)mmap(0, map_size, PROT_READ, MAP_FILE | MAP_SHARED, fd,
-                             (off_t)(offset - pg_offset))) == (char *)-1) {
+       if ((p = mmap(0, map_size, PROT_READ, MAP_FILE | MAP_SHARED, fd,
+                     (off_t)(offset - pg_offset))) == MAP_FAILED) {
                prterr("domapread: mmap");
                report_failure(190);
        }
+       if (!quiet && (debug > 1 &&
+                       (monitorstart == -1 ||
+                        (offset + size > monitorstart &&
+                         (monitorend == -1 || offset <= monitorend))))) {
+               gettimeofday(&t, NULL);
+               prt("       %lu.%06lu mmap done\n", t.tv_sec, t.tv_usec);
+       }
        memcpy(temp_buf, p + pg_offset, size);
+       if (!quiet && (debug > 1 &&
+                       (monitorstart == -1 ||
+                        (offset + size > monitorstart &&
+                         (monitorend == -1 || offset <= monitorend))))) {
+               gettimeofday(&t, NULL);
+               prt("       %lu.%06lu memcpy done\n", t.tv_sec, t.tv_usec);
+       }
        if (munmap(p, map_size) != 0) {
                prterr("domapread: munmap");
                report_failure(191);
        }
+       if (!quiet && (debug > 1 &&
+                       (monitorstart == -1 ||
+                        (offset + size > monitorstart &&
+                         (monitorend == -1 || offset <= monitorend))))) {
+               gettimeofday(&t, NULL);
+               prt("       %lu.%06lu munmap done\n", t.tv_sec, t.tv_usec);
+       }
 
        check_buffers(offset, size);
 }
@@ -585,7 +610,7 @@ dowrite(unsigned offset, unsigned size)
                        (monitorstart == -1 ||
                         (offset + size > monitorstart &&
                          (monitorend == -1 || offset <= monitorend))))))
-               prt("%lu %lu.%lu write\t0x%x thru\t0x%x\t(0x%x bytes)\n",
+               prt("%06lu %lu.%06lu write      %#08x thru %#08x\t(0x%x bytes)\n",
                    testcalls, t.tv_sec, t.tv_usec, offset, offset + size - 1,
                    size);
        ret = lseek(fd, (off_t)offset, SEEK_SET);
@@ -594,6 +619,13 @@ dowrite(unsigned offset, unsigned size)
                report_failure(150);
        }
        iret = write(fd, good_buf + offset, size);
+       if (!quiet && (debug > 1 &&
+                       (monitorstart == -1 ||
+                        (offset + size > monitorstart &&
+                         (monitorend == -1 || offset <= monitorend))))) {
+               gettimeofday(&t, NULL);
+               prt("       %lu.%06lu write done\n", t.tv_sec, t.tv_usec);
+       }
        if (iret != size) {
                if (iret == -1)
                        prterr("dowrite: write");
@@ -646,7 +678,7 @@ domapwrite(unsigned offset, unsigned size)
                        (monitorstart == -1 ||
                         (offset + size > monitorstart &&
                          (monitorend == -1 || offset <= monitorend))))))
-               prt("%lu %lu.%lu mapwrite\t0x%x thru\t0x%x\t(0x%x bytes)\n",
+               prt("%06lu %lu.%06lu mapwrite   %#08x thru %#08x\t(0x%x bytes)\n",
                    testcalls, t.tv_sec, t.tv_usec, offset, offset + size - 1,
                    size);
 
@@ -655,25 +687,59 @@ domapwrite(unsigned offset, unsigned size)
                        prterr("domapwrite: ftruncate");
                        exit(201);
                }
+               if (!quiet && (debug > 1 &&
+                              (monitorstart == -1 ||
+                               (offset + size > monitorstart &&
+                                (monitorend == -1 || offset <= monitorend))))) {
+                       gettimeofday(&t, NULL);
+                       prt("       %lu.%06lu truncate done\n", t.tv_sec, t.tv_usec);
+       }
        }
        pg_offset = offset & page_mask;
        map_size  = pg_offset + size;
 
-       if ((p = (char *)mmap(0, map_size, PROT_READ | PROT_WRITE,
-                             MAP_FILE | MAP_SHARED, fd,
-                             (off_t)(offset - pg_offset))) == (char *)-1) {
+       if ((p = mmap(0, map_size, PROT_READ | PROT_WRITE, MAP_FILE|MAP_SHARED,
+                     fd, (off_t)(offset - pg_offset))) == MAP_FAILED) {
                prterr("domapwrite: mmap");
                report_failure(202);
        }
+       if (!quiet && (debug > 1 &&
+                       (monitorstart == -1 ||
+                        (offset + size > monitorstart &&
+                         (monitorend == -1 || offset <= monitorend))))) {
+               gettimeofday(&t, NULL);
+               prt("       %lu.%06lu mmap done\n", t.tv_sec, t.tv_usec);
+       }
        memcpy(p + pg_offset, good_buf + offset, size);
+       if (!quiet && (debug > 1 &&
+                       (monitorstart == -1 ||
+                        (offset + size > monitorstart &&
+                         (monitorend == -1 || offset <= monitorend))))) {
+               gettimeofday(&t, NULL);
+               prt("       %lu.%06lu memcpy done\n", t.tv_sec, t.tv_usec);
+       }
        if (msync(p, map_size, 0) != 0) {
                prterr("domapwrite: msync");
                report_failure(203);
        }
+       if (!quiet && (debug > 1 &&
+                       (monitorstart == -1 ||
+                        (offset + size > monitorstart &&
+                         (monitorend == -1 || offset <= monitorend))))) {
+               gettimeofday(&t, NULL);
+               prt("       %lu.%06lu msync done\n", t.tv_sec, t.tv_usec);
+       }
        if (munmap(p, map_size) != 0) {
                prterr("domapwrite: munmap");
                report_failure(204);
        }
+       if (!quiet && (debug > 1 &&
+                       (monitorstart == -1 ||
+                        (offset + size > monitorstart &&
+                         (monitorend == -1 || offset <= monitorend))))) {
+               gettimeofday(&t, NULL);
+               prt("       %lu.%06lu munmap done\n", t.tv_sec, t.tv_usec);
+       }
 }
 
 
@@ -703,13 +769,17 @@ dotruncate(unsigned size)
        if ((progressinterval && testcalls % progressinterval == 0) ||
            (debug && (monitorstart == -1 || monitorend == -1 ||
                       size <= monitorend)))
-               prt("%lu %lu.%lu trunc\tfrom 0x%x to 0x%x\n",
+               prt("%06lu %lu.%06lu trunc from %#08x  to  %#08x\n",
                    testcalls, t.tv_sec, t.tv_usec, oldsize, size);
        if (ftruncate(fd, (off_t)size) == -1) {
                prt("ftruncate1: %x\n", size);
                prterr("dotruncate: ftruncate");
                report_failure(160);
        }
+       if (!quiet && debug > 1) {
+               gettimeofday(&t, NULL);
+               prt("       %lu.%06lu trunc done\n", t.tv_sec, t.tv_usec);
+       }
 }
 
 
@@ -747,20 +817,29 @@ docloseopen(void)
        if (testcalls <= simulatedopcount)
                return;
 
+       gettimeofday(&t, NULL);
        log4(OP_CLOSEOPEN, file_size, (unsigned)file_size, 0, &t);
 
-       gettimeofday(&t, NULL);
        if (debug)
-               prt("%lu %lu.%lu close/open\n", testcalls, t.tv_sec, t.tv_usec);
+               prt("%06lu %lu.%06lu close/open\n", testcalls, t.tv_sec,
+                   t.tv_usec);
        if (close(fd)) {
                prterr("docloseopen: close");
                report_failure(180);
        }
+       if (!quiet && debug > 1) {
+               gettimeofday(&t, NULL);
+               prt("       %lu.%06lu close done\n", t.tv_sec, t.tv_usec);
+       }
        fd = open(fname, O_RDWR, 0);
        if (fd < 0) {
                prterr("docloseopen: open");
                report_failure(181);
        }
+       if (!quiet && debug > 1) {
+               gettimeofday(&t, NULL);
+               prt("       %lu.%06lu open done\n", t.tv_sec, t.tv_usec);
+       }
 }
 
 
@@ -782,9 +861,6 @@ test(void)
 
        testcalls++;
 
-       if (closeprob)
-               closeopen = (rv >> 3) < (1 << 28) / closeprob;
-
        if (debugstart > 0 && testcalls >= debugstart)
                debug = 1;
 
@@ -831,7 +907,7 @@ test(void)
        }
        if (sizechecks && testcalls > simulatedopcount)
                check_size();
-       if (closeopen)
+       if (closeprob && (rv >> 3) < (1 << 28) / closeprob)
                docloseopen();
 }
 
@@ -851,33 +927,33 @@ void
 usage(void)
 {
        fprintf(stdout, "usage: %s",
-               "fsx [-dnqLOW] [-b opnum] [-c Prob] [-l flen] [-m
-start:end] [-o oplen] [-p progressinterval] [-r readbdy] [-s style] [-t
-truncbdy] [-w writebdy] [-D startingop] [-N numops] [-P dirpath] [-S seed]
-fname\n\
-       -b opnum: beginning operation number (default 1)\n\
-       -c P: 1 in P chance of file close+open at each op (default infinity)\n\
-       -d: debug output for all operations\n\
-       -l flen: the upper bound on file size (default 262144)\n\
-       -m startop:endop: monitor (print debug output) specified byte range
-(default 0:infinity)\n\
-       -n: no verifications of file size\n\
-       -o oplen: the upper bound on operation size (default 65536)\n\
-       -p progressinterval: debug output at specified operation interval\n\
-       -q: quieter operation\n\
-       -r readbdy: 4096 would make reads page aligned (default 1)\n\
-       -s style: 1 gives smaller truncates (default 0)\n\
-       -t truncbdy: 4096 would make truncates page aligned (default 1)\n\
-       -w writebdy: 4096 would make writes page aligned (default 1)\n\
-       -D startingop: debug output starting at specified operation\n\
-       -L: fsxLite - no file creations & no file size changes\n\
-       -N numops: total # operations to do (default infinity)\n\
-       -O: use oplen (see -o flag) for every op (default random)\n\
-       -P: save .fsxlog and .fsxgood files in dirpath (default ./)\n\
-       -S seed: for random # generator (default 1) 0 gets timestamp\n\
-       -W: mapped write operations DISabled\n\
-        -R: read() system calls only (mapped reads disabled)\n\
-       fname: this filename is REQUIRED (no default)\n");
+               "fsx [-dnqLOW] [-b opnum] [-c Prob] [-l flen] [-m "
+"start:end] [-o oplen] [-p progressinterval] [-r readbdy] [-s style] [-t "
+"truncbdy] [-w writebdy] [-D startingop] [-N numops] [-P dirpath] [-S seed] "
+"fname\n"
+"      -b opnum: beginning operation number (default 1)\n"
+"      -c P: 1 in P chance of file close+open at each op (default infinity)\n"
+"      -d: debug output for all operations [-d -d = more debugging]\n"
+"      -l flen: the upper bound on file size (default 262144)\n"
+"      -m startop:endop: monitor (print debug output) specified byte rang"
+"(default 0:infinity)\n"
+"      -n: no verifications of file size\n"
+"      -o oplen: the upper bound on operation size (default 65536)\n"
+"      -p progressinterval: debug output at specified operation interval\n"
+"      -q: quieter operation\n"
+"      -r readbdy: 4096 would make reads page aligned (default 1)\n"
+"      -s style: 1 gives smaller truncates (default 0)\n"
+"      -t truncbdy: 4096 would make truncates page aligned (default 1)\n"
+"      -w writebdy: 4096 would make writes page aligned (default 1)\n"
+"      -D startingop: debug output starting at specified operation\n"
+"      -L: fsxLite - no file creations & no file size changes\n"
+"      -N numops: total # operations to do (default infinity)\n"
+"      -O: use oplen (see -o flag) for every op (default random)\n"
+"      -P: save .fsxlog and .fsxgood files in dirpath (default ./)\n"
+"      -S seed: for random # generator (default 1) 0 gets timestamp\n"
+"      -W: mapped write operations DISabled\n"
+"        -R: read() system calls only (mapped reads disabled)\n"
+"      fname: this filename is REQUIRED (no default)\n");
        exit(90);
 }
 
@@ -944,8 +1020,8 @@ main(int argc, char **argv)
                case 'b':
                        simulatedopcount = getnum(optarg, &endp);
                        if (!quiet)
-                               fprintf(stdout, "Will begin at operation
-%ld\n",
+                               fprintf(stdout, "Will begin at operation"
+                                       "%ld\n",
                                        simulatedopcount);
                        if (simulatedopcount == 0)
                                usage();
@@ -961,7 +1037,7 @@ main(int argc, char **argv)
                                usage();
                        break;
                case 'd':
-                       debug = 1;
+                       debug++;
                        break;
                case 'l':
                        maxfilelen = getnum(optarg, &endp);
@@ -1130,8 +1206,8 @@ main(int argc, char **argv)
                                prterr(fname);
                                warn("main: error on write");
                        } else
-                               warn("main: short write, 0x%x bytes instead
-of 0x%x\n",
+                               warn("main: short write, 0x%x bytes instead"
+                                       "of 0x%x\n",
                                     (unsigned)written, maxfilelen);
                        exit(98);
                }