why system call unlink so slow?

Question

#include <unistd.h>
#include <stdio.h>

void dump_log(int size){
    char cmd[1024];
    snprintf(cmd, sizeof(cmd)/sizeof(cmd[0]), "dd if=/dev/zero of=from.bin bs=1024 count=%d", size);
    int ret = system(cmd);
    if (ret<0){
        perror("system");
    }

}

int main(){    
    const char *filepath = "from.bin";

    while(1){
        dump_log(1024*100);
        sleep(10);
        unlink(filepath);
    }

    return 0;
}

strace -T ./a.out show this:

unlink("from.bin")                      = 0 <0.019916>

unlink a file(100M) spend 19ms, what happen when unlink a file? why so slow?

system information: linux 3.13.0-57-generic , Ubuntu 14.04.2 LTS, ext4

Answer 1

If you have a huge file to unlink(2) the kernel doesn't unlock the inode until all the blocks pointers are returned to the free block list. You can check the difference in time by making a second link (which will make the unlink only to release the link you are deleting, without releasing any block). By specification, the code releasing all those blocks is your process (well, running in kernel mode, not usermode, but there's no reserved process to return the blocks to the free list) and it will not return until it has released all the blocks.

Example: (edit)

The following code will illustrate this:

#include <errno.h>
#include <getopt.h>
#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include <time.h>

#define D(X) "%s:%d:%s: " X, __FILE__, __LINE__, __func__

int main(int argc, char **argv)
{
    int opt, i;

    while ((opt = getopt(argc, argv, "")) != EOF) {
        switch (opt) {
        } /* switch */
    } /* while */

    argc -= optind; argv += optind;

    for (i = 0; i < argc; i++) {
        struct timespec now, then; 
        int res;

        res = clock_gettime(CLOCK_THREAD_CPUTIME_ID, &now);
        if (res < 0) {
            fprintf(stderr,
                    D("ERROR: %s (errno = %d)\n"),
                    strerror(errno), errno);
            exit(EXIT_FAILURE);
        } /* if */

        unlink(argv[i]);

        res = clock_gettime(CLOCK_THREAD_CPUTIME_ID, &then);
        if (res < 0) {
            fprintf(stderr, D("ERROR: %s (errno = %d)\n"),
                    strerror(errno), errno);
            exit(EXIT_FAILURE);
        } /* if */
        then.tv_nsec -= now.tv_nsec;
        then.tv_sec -= now.tv_sec;
        if (then.tv_nsec < 0) {
            then.tv_nsec += 1000000000L;
            then.tv_sec--;
        } /* if */
        printf(D("%s: %d.%09d s. (CPU time)\n"),
                argv[i], then.tv_sec, then.tv_nsec);
    } /* for */
    exit(EXIT_SUCCESS);
} /* main */

Then I construct a 2Gb file with this command:

$ yes | dd of=pepe bs=1M iflag=fullblock count=2048

Then I make 32 links to this file:

i=0
while [ "$i" -lt 32 ]
do ln pepe pepe$i
   i=$(expr $i + 1)
done

Then I run the following command (which shows only CPU time):

$ unlink pepe[0-9]* pepe
unlink.c:47:main: pepe0: 0.000074272 s. (CPU time)
unlink.c:47:main: pepe1: 0.000022722 s. (CPU time)
unlink.c:47:main: pepe10: 0.000015034 s. (CPU time)
unlink.c:47:main: pepe11: 0.000013254 s. (CPU time)
unlink.c:47:main: pepe12: 0.000012827 s. (CPU time)
unlink.c:47:main: pepe13: 0.000012462 s. (CPU time)
unlink.c:47:main: pepe14: 0.000012241 s. (CPU time)
unlink.c:47:main: pepe15: 0.000012753 s. (CPU time)
unlink.c:47:main: pepe16: 0.000012517 s. (CPU time)
unlink.c:47:main: pepe17: 0.000012245 s. (CPU time)
unlink.c:47:main: pepe18: 0.000013104 s. (CPU time)
unlink.c:47:main: pepe19: 0.000012491 s. (CPU time)
unlink.c:47:main: pepe2: 0.000012662 s. (CPU time)
unlink.c:47:main: pepe20: 0.000012606 s. (CPU time)
unlink.c:47:main: pepe21: 0.000012803 s. (CPU time)
unlink.c:47:main: pepe22: 0.000012597 s. (CPU time)
unlink.c:47:main: pepe23: 0.000012391 s. (CPU time)
unlink.c:47:main: pepe24: 0.000012582 s. (CPU time)
unlink.c:47:main: pepe25: 0.000012557 s. (CPU time)
unlink.c:47:main: pepe26: 0.000012386 s. (CPU time)
unlink.c:47:main: pepe27: 0.000012261 s. (CPU time)
unlink.c:47:main: pepe28: 0.000012245 s. (CPU time)
unlink.c:47:main: pepe29: 0.000012351 s. (CPU time)
unlink.c:47:main: pepe3: 0.000011940 s. (CPU time)
unlink.c:47:main: pepe30: 0.000013003 s. (CPU time)
unlink.c:47:main: pepe31: 0.000012231 s. (CPU time)
unlink.c:47:main: pepe4: 0.000012777 s. (CPU time)
unlink.c:47:main: pepe5: 0.000012546 s. (CPU time)
unlink.c:47:main: pepe6: 0.000012461 s. (CPU time)
unlink.c:47:main: pepe7: 0.000013129 s. (CPU time)
unlink.c:47:main: pepe8: 0.000012311 s. (CPU time)
unlink.c:47:main: pepe9: 0.000012446 s. (CPU time)
unlink.c:47:main: pepe: 0.195457587 s. (CPU time)

As you see, all but the last link take around 12 microseconds, but the last is almost two tenths of a second to execute.