Strange NFS/async write issue

[William Dauchy <william@gandi.net>]

[-- Attachment #1.1: Type: text/plain, Size: 3138 bytes --]

Hello Trond,

We wrote the attached tester to reproduce an issue we have with mysql on
a 3.9.8 kernel using a nfsv4 mount. 

mount options are "classic":

rw,nosuid,nodev,noexec,relatime,vers=4.0,rsize=1048576,wsize=1048576,namlen=255,hard,proto=tcp,timeo=600,retrans=2,sec=sys,local_lock=none

When handling a temporary file, mysql open(), then writes a bunch (say ~16MB) of data
to that file, lseeks to the start and re-reads file contents.

With the code as attached, we see a lot of small NFS writes (1400 bytes) and
a lot of getattrs [1] and the test takes a little more than 2 seconds.

It seems the lseek/read are serialized to the last write actually sent to the filer - 
and nothing aggregates the big writes.

If we uncomment the fsync() call, or simply close() and reopen the file, the test
completes in a few milliseconds. Same if we call sync() from any process while this
test is running. Dump shows lots of big tcp pushes, few NFS commands/answers - no
getattr in between writes.

Is this an issue worth a dig or a known behaviour?
Can we debug this a bit further for you?

Thanks for your time,

[1]
(extract from the dump:
15:56:43.681766 IP 10.0.46.65.813 > 10.0.41.39.2049: Flags [P.], seq 14399980:14401384, ack 1038253, win 24576, options [nop,nop,TS val 928349822 ecr 259987202], length 1404
15:56:43.685189 IP 10.0.41.39.2049 > 10.0.46.65.813: Flags [.], ack 14399980, win 32715, options [nop,nop,TS val 259987203 ecr 928349822], length 0
15:56:43.689131 IP 10.0.41.39.2049 > 10.0.46.65.263281194: reply ok 132 getattr NON 3 ids 0/38 sz 0
15:56:43.689292 IP 10.0.46.65.280058410 > 10.0.41.39.2049: 2892 getattr fh 0,0/22
15:56:43.689330 IP 10.0.46.65.813 > 10.0.41.39.2049: Flags [P.], seq 14404280:14405684, ack 1038389, win 24576, options [nop,nop,TS val 928349824 ecr 259987203], length 1404
15:56:43.690127 IP 10.0.41.39.2049 > 10.0.46.65.813: Flags [.], ack 14404280, win 32715, options [nop,nop,TS val 259987203 ecr 928349824], length 0
15:56:43.690651 IP 10.0.41.39.2049 > 10.0.46.65.280058410: reply ok 132 getattr NON 3 ids 0/38 sz 0
15:56:43.690769 IP 10.0.46.65.296835626 > 10.0.41.39.2049: 2892 getattr fh 0,0/22
15:56:43.690782 IP 10.0.46.65.813 > 10.0.41.39.2049: Flags [P.], seq 14408580:14409984, ack 1038525, win 24576, options [nop,nop,TS val 928349824 ecr 259987203], length 1404
15:56:43.691496 IP 10.0.41.39.2049 > 10.0.46.65.813: Flags [.], ack 14408580, win 32715, options [nop,nop,TS val 259987203 ecr 928349824], length 0
15:56:43.692970 IP 10.0.41.39.2049 > 10.0.46.65.296835626: reply ok 132 getattr NON 3 ids 0/38 sz 0
15:56:43.693194 IP 10.0.46.65.313612842 > 10.0.41.39.2049: 2892 getattr fh 0,0/22
15:56:43.693249 IP 10.0.46.65.813 > 10.0.41.39.2049: Flags [P.], seq 14412880:14414284, ack 1038661, win 24576, options [nop,nop,TS val 928349825 ecr 259987204], length 1404
15:56:43.693395 IP 10.0.41.39.2049 > 10.0.46.65.813: Flags [.], ack 14412880, win 32715, options [nop,nop,TS val 259987204 ecr 928349825], length 0
15:56:43.693644 IP 10.0.41.39.2049 > 10.0.46.65.313612842: reply ok 132 getattr NON 3 ids 0/38 sz 0
)

-- 
William

[-- Attachment #1.2: nfssync.c --]
[-- Type: text/x-csrc, Size: 1213 bytes --]

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

int main(int argc, char **argv)
{
    int i, fd;
    time_t ts;
    char *fakebuf;

    if (argc < 2)
        exit(1);

    fd = open(argv[1], O_RDWR|O_CREAT|O_EXCL|O_TRUNC|O_NOFOLLOW, 0755);
    if (fd < 0) {
        perror("open");
        exit(1);
    }

    fakebuf = malloc(256*1024);
    if (fakebuf == NULL) {
        perror("malloc");
        exit(1);
    }

    ts = time(NULL);
    printf("writing..");
    memset(fakebuf, 'A', 256*1024);
    for (i = 0; i < 68; i++)
        write(fd, fakebuf, 256*1024);
    printf("done in %lu secs\n", time(NULL) - ts);

    ts = time(NULL);
    printf("not syncing..");
    // fsync(fd);
    printf("synced in %lu secs\n", time(NULL) - ts);

    printf("reading..");

    ts = time(NULL);
    if (fd < 0) {
        perror("open");
        exit(1);
    }

    // just mimic mysql stuff
    lseek(fd, 0, SEEK_CUR);
    lseek(fd, 0, SEEK_END);
    lseek(fd, 0, SEEK_SET);
    for (i = 0; i < 68; i++)
        read(fd, fakebuf, 256*1024);
    printf("done in %lu secs\n", time(NULL) - ts);

    return 0;
}

[-- Attachment #2: Digital signature --]
[-- Type: application/pgp-signature, Size: 198 bytes --]