Re: svn commit: r109866 - /httpd/httpd/trunk/modules/loggers/mod_log_config.c

[Joe Orton]

On Sun, Dec 05, 2004 at 01:58:44PM -0700, Paul Querna wrote:
> Joe Orton wrote:
> >On Sun, Dec 05, 2004 at 07:05:23AM -0000, Paul Querna wrote:
> >
> >>Author: pquerna
> >>Date: Sat Dec  4 23:05:23 2004
> >>New Revision: 109866
> >>
> >>URL: http://svn.apache.org/viewcvs?view=rev&rev=109866
> >>Log:
> >>mod_log_config.c: Use iovecs to write the log line to eliminate a memcpy
> >
> >
> >IIRC, writev'ing several small blocks to a file is actually generally
> >more expensive than doing a memcpy in userspace and calling write.  Did
> >you benchmark this to be faster/better/...?
> >

also that introduced a warning:

mod_log_config.c: In function `ap_default_log_writer':
mod_log_config.c:1353: warning: assignment discards qualifiers from pointer 
target type

> I did a local mini-benchmark of write w/ memcpy vs writev... and they 
> came out to almost exactly the same on average with small sets of data.

I remember I checked this before too... try the attached compiled with
or without -DUSE_WRITEV, copy-and-write comes out about ~10-20% faster
than writev on Linux 2.6/ext3 here for a real log vector, or did I screw
up the benchmark?

rm -f writev.out; sync; sleep 5
./writev-copy
copy+write: 7s330676.
rm -f writev.out; sync; sleep 5
./writev-copy
copy+write: 7s327580.
rm -f writev.out; sync; sleep 5
./writev-copy
copy+write: 7s360685.
rm -f writev.out; sync; sleep 5
./writev-writev
writev: 8s893524.
rm -f writev.out; sync; sleep 5
./writev-writev
writev: 8s808458.
rm -f writev.out; sync; sleep 5
./writev-writev
writev: 9s052335.

joe

#include <sys/time.h>
#include <sys/uio.h>
#include <sys/stat.h>
#include <fcntl.h>
#include <unistd.h>
#include <stdio.h>
#include <string.h>
#include <stdlib.h>

char *strs[] = {
    "127.0.0.1", 
    " ",
    "-",
    " ",
    "-",
    " ",
    "[22/Jul/2003:12:09:58 +0100]",
    " \"",
    "GET / HTTP/1.0",
    "\" ",
    "200",
    " ",
    "1456",
    "\n"
};

#define NVECS (sizeof(strs) / sizeof(char *))
#define ITERS (1000000)

#ifdef USE_WRITEV
static void do_writev(int fd, struct iovec *vec, size_t nvec, size_t total)
{
    ssize_t ret = writev(fd, vec, nvec);
    
    if (ret != total) {
        printf("writev got %d not %u\n", ret, total);
    }
}
#else
static void do_writev(int fd, struct iovec *vec, size_t nvec, size_t total)
{
    char *p, *buf;
    ssize_t ret;

    p = buf = malloc(total);
    while (nvec) {
        memcpy(p, vec[0].iov_base, vec[0].iov_len);
        p += vec[0].iov_len;
        nvec--;
        vec++;
    }

    ret = write(fd, buf, total);
    free(buf);
    if (ret != total) {
        printf("write got %d not %u\n", ret, total);
    }
}
#endif

#define BIG 100

#define TESTFN "./writev.out"

int main(int argc, char **argv)
{
    int fd;
    size_t n, total = 0;
    struct iovec vecs[NVECS];
    int count = 0;
    struct timeval start, end, diff;

    unlink(TESTFN);

    fd = open(TESTFN, O_CREAT | O_WRONLY | O_TRUNC, 0644);

    if (fd < 0) {
        perror("open");
        return 1;
    }
    
#if 0
    for (n = 1; n < 5; n++) {
        strs[n] = malloc(BIG * n + 1);
        memset(strs[n], 'a' + n, BIG * n);
        strs[n][BIG * n] = 0;
    }
#endif

    for (n = 0; n < NVECS; n++) {
        vecs[n].iov_base = strs[n];
        vecs[n].iov_len = strlen(strs[n]);
        total += vecs[n].iov_len;
    }

    gettimeofday(&start, NULL);

    while (count++ < ITERS)
        do_writev(fd, vecs, NVECS, total);

    gettimeofday(&end, NULL);
    
    timersub(&end, &start, &diff);

#ifdef USE_WRITEV
    printf("writev");
#else
    printf("copy+write");
#endif

    printf(": %lds%06ld.\n", diff.tv_sec, diff.tv_usec);

    close(fd);
    return 0;
}