Re: first mkdir takes a long time (on ext3)

[vogelke+debian@pobox.com (Karl Vogel)]

>> On 19/05/11 17:01, Hartmut Niemann wrote:
H> It often takes very long time (20s) to mkdir on an ext3 drive

>> Am Fr Mai 20 2011 schrieb Karl Vogel:
K> What does "strace mkdir /some/directory" show?

>> On Fri, 20 May 2011 08:38:41 +0200, <Hartmut.Niemann@gmx.de> said:
H> $ strace mkdir two
H> execve("/bin/mkdir", ["mkdir", "two"], [/* 18 vars */]) = 0
H> brk(0)                               = 0x9342000
H> access("/etc/ld.so.nohwcap", F_OK)   = -1 ENOENT (No such file ...
H> mmap2(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS...
H> access("/etc/ld.so.preload", R_OK)   = -1 ENOENT (No such file ...
H> open("/etc/ld.so.cache", O_RDONLY)   = 3
H> fstat64(3, {st_mode=S_IFREG|0644, st_size=41270, ...}) = 0
H> mmap2(NULL, 41270, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb78be000
H> close(3)                             = 0
H> access("/etc/ld.so.nohwcap", F_OK)   = -1 ENOENT (No such file ...
H> open("/lib/libselinux.so.1", O_RDONLY)  = 3
H> ...

   I installed a more recent version of GNU coreutils from source, and
   compared /bin/mkdir to /usr/local/bin/mkdir.  I found /bin/mkdir gives
   output like yours, but the /usr/local output is much shorter and doesn't
   include any references to selinux:

     me% strace -r /usr/local/bin/mkdir three
     0.000000 execve("/usr/local/bin/mkdir", ["mkdir", "three"], ...
     0.000480 brk(0) = 0x196f2000
     0.000076 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|...
     0.000085 uname({sys="Linux", node="cmswbk002", ...}) = 0
     0.000139 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such ...
     0.000099 open("/etc/ld.so.cache", O_RDONLY) = 3
     0.000066 fstat(3, {st_mode=S_IFREG|0644, st_size=67370, ...}) = 0
     0.000103 mmap(NULL, 67370, PROT_READ, MAP_PRIVATE, 3, 0) = ...
     0.000055 close(3) = 0
     0.000071 open("/lib64/libc.so.6", O_RDONLY) = 3
     0.000065 read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\...
     0.000073 fstat(3, {st_mode=S_IFREG|0755, st_size=1717800, ...}) =...
     0.000093 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_A...
     0.000071 mmap(0x32bce00000, 3498328, PROT_READ|PROT_EXEC, MAP_PRI...
     0.000079 mprotect(0x32bcf4e000, 2093056, PROT_NONE) = 0
     0.000063 mmap(0x32bd14d000, 20480, PROT_READ|PROT_WRITE, MAP_PRIV...
     0.000078 mmap(0x32bd152000, 16728, PROT_READ|PROT_WRITE, MAP_PRIV...
     0.000062 close(3) = 0
     0.000071 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_A...
     0.000060 arch_prctl(ARCH_SET_FS, 0x2ae92dd5f230) = 0
     0.000143 mprotect(0x32bd14d000, 16384, PROT_READ) = 0
     0.000069 mprotect(0x32bc01b000, 4096, PROT_READ) = 0
     0.000056 munmap(0x2ae92dd4d000, 67370) = 0
     0.000141 mkdir("three", 0777) = 0
     0.000148 close(1) = 0
     0.000060 close(2) = 0
     0.000062 exit_group(0) = ?

   "-r" prints a relative timestamp upon entry to each system call.

H> This run was fast (less than 1 second).  Unfortunately I do not know
H> when mkdir takes long and can't reproduce it today, so I can't tell
H> whether a strace of a slow mkdir is different.

   Try this version of mkdir earlier in your PATH until you find out what
   the delay is.

     you% mkdir /tmp/mkdir
     you% chmod 1777 /tmp/mkdir

     you% cat /usr/local/bin/mkdir
     #!/bin/sh
     tfile=$(date '+%Y%m%d%H%M%S')
     exec /usr/bin/strace -r -o /tmp/mkdir/$tfile /bin/mkdir ${1+"$@"}
     exit 1

-- 
Karl Vogel                      I don't speak for the USAF or my company

NyQuil -The stuffy, sneezy, why-the-hell-is-the-room-spinning medicine.
                                                     --seen on T-shirt