Order of traversing files in a directory

[verygreen]

Moving from #325 in a ticket of its own.

While looking around Archiver::_process I noticed that:

            if not dry_run:
                status = archive.process_dir(path, st)
            try:
                entries = os.listdir(path)
            except OSError as e:
                status = 'E'
                self.print_warning('%s: %s', path, e)
            else:
                for filename in sorted(entries):
                    entry_path = os.path.normpath(os.path.join(path, filename))
                    self._process(archive, cache, matcher, exclude_caches, exclude_if_present,
                                  keep_tag_files, skip_inodes, entry_path, restrict_dev,
                                  read_special=read_special, dry_run=dry_run)

I imagine the sort(entries) just sorts stuff alphabetically? If so, this is a pretty bad idea on a bunch of filesystems for large directories on spinning media. Affected filesystems include reiserfs, ext4 and probably many more that have static inode allocation.
The problem at hand is when you sort this list in an order different than inode numbers, every lstat that you do seeks the disk to a different inode table block somewhere which is really slow.
Not sorting the output is also not an option since then you get some "random" underlying hash sorting that also might not correspond to creation order. The most optimal strategy here for things with fixed inode tables is to sort by inode number (available in readdir output).
For filesystems with no static inode tables (like reiserfs) I imagine that would also lead to desired effect because it still is a good proxy for create time that leads to ondisk location (earlier created files get closer to start of disk in a chunk if they were written together).
More advanced COW filesystems like zfs and bttrfs - I am less sure, those might be all over the place depending on a bunch of stuff, though. I assume sort ordering would not matter there all that much.

A question was also raised if this makes any practical difference. And it certainly does for large directories (with millions of entries) that are not cached.
Here are some links to ext3 discussions about when htree code became popular and discussion arose. You'll see that performance impact is quite high:
https://bugzilla.kernel.org/show_bug.cgi?id=417
https://lkml.org/lkml/2008/2/18/263

There are tons more and the same issue is present in other filesystems with hashed names. I know about this because I am a Linux fs developer on my day job (and we met this when I was still working on reiserfs).

Additionally as we look outside of Linux (which is really optimized in these areas), other systems caches are (in some cases? in many cases) a lot more suboptimal or even non-exstent (e.g. in BSD where every fs driver used to need to implement their own cache).
I had a big confirmation of this yesterday. So I had a ~2M structure of files in on my Linux server, all on rotating media. find / -perm 0 (to cause stat calls) took 15 seconds there.
Now I also have this macbook I am working on, it has ssd and about 2.5M files on it, same find takes 2m50s. Quite a difference thanks to many-many variables I am sure.

[enkore]

If this has no functional reason - and I don't think it has - then we can just drop that sorting; since it's still a DFS traversal the usual directory-before-containing-files assertion holds. Some care should still be taken that we are not missing anything that depends on it.

[verygreen]

The thing is, if you drop the sorting altogether, you don't gain anything.
What I am trying to say is that it would be great if you can sort on inode number (at least for some filesystems).

[enkore]

Stupid question: I always thought directory order ~ inode order of the dirents ... so that's probably wrong, or at least impl. defined?

[verygreen]

Readdir order is usually the order the names are laid out in the directory itself. (but intermediate layers and some filesystems might reorder stuff - see the library referenced for example).

For simple filesystems readdir order is also the order in which files were created. But more modern systems use "name hash" to help with lookups, so readdir order and file creation orders are quite different.

What this leads to is:
When I do for i inseq 1000; do touch $i ; done

and then do ls -U, I get back my files in random order.
When caches are cold and I try to do stat on them in that readdir order - that makes hdd heads move all around from one inode table to another instead of moving nicely sequentially as I progress the files in the creation order.

[enkore]

Does this change things significantly for OSX? feature/inorder

N.b. experimental code, different error handling characteristics, probably eats your cat ;-)

Also, the actual entries are not stat'ed in inode order, because, uh, we seem to need stat to get to the inode of the entries. So, this shouldn't make a difference after all. Something I am missing here? -- ah, scandir will do. brb.

[verygreen]

If I read this correctly (And this reminds me some perl confusing constructions now ;) ) it gets the readdir output, and then the "map" thing calls lstat on every element and then you sort based on inode number from struct stat?
This is not going to help because it's everybody's guess what order you do lstat calls in (probably native readdir order?).

Instead, when you do readdir you get a dirent structure (similar to other OSes too):

           struct old_linux_dirent {
               long  d_ino;              /* inode number */
               off_t d_off;              /* offset to this old_linux_dirent */
               unsigned short d_reclen;  /* length of this d_name */
               char  d_name[NAME_MAX+1]; /* filename (null-terminated) */
           }

So you already have the inode number in the readdir output and that's all you need to do the sorting. - Whenever python shows you this detail - I don't know. But if you plan to do stat beforehand, then might as well not bother sorting.

Also modern systems don't use readdir(2). but getdents64(2) that returns you:

           struct linux_dirent {
               unsigned long  d_ino;     /* Inode number */
               unsigned long  d_off;     /* Offset to next linux_dirent */
               unsigned short d_reclen;  /* Length of this linux_dirent */
               char           d_name[];  /* Filename (null-terminated) */
                                 /* length is actually (d_reclen - 2 -
                                    offsetof(struct linux_dirent, d_name)) */
               /*
               char           pad;       // Zero padding byte
               char           d_type;    // File type (only since Linux
                                         // 2.6.4); offset is (d_reclen - 1)
               */
           }

Now, this in addition to all other things also brings you the d_type - from which you can know what file type is that name correspond to without doing stat (useful in various workloads, as stat is actually quite heavy in many cases, but borg needs to do stat anyway so probably of no significant importance here, esp. since it's not portable).

[enkore]

Yes, I noticed now as well. I pushed a new version which uses Pythons scandir instead, which from the looks of it is a quite thin wrapper around readdir. This should now really sort-then-stat.

This makes a consistent performance difference for me, about 10 seconds for

/bin/time sudo borg create testrepo::1234 --dry-run / -x

with master, but only ~4.5 seconds with this. Maybe I put a bug in that skips every other file? :-)

[ThomasWaldmann]

scandir is in stdlib since 3.5, so if we use that before requiring >= 3.5, we would need to add the scandir pypi package as addtl. dependency.

[ThomasWaldmann]

Can you redo your measurement for both versions, for both hot and cold cache?

[verygreen]

Now this looks mostly good.

The only concern I have left is - does os.scandir return you fully qualified path name so you no longer need to do entry_path = os.path.normpath(os.path.join(path, filename)) or was that an omission?

[enkore]

dirent.path is absolute if path in scandir(path) was absolute. So. Not sure. Didn't test if this is the same thing as before.

Thomas: We could just make it a soft-dependency, if this proves to be a worthwhile improvement.

Edit: The difference comes mainly from listdir vs scandir it seems, not sorting scandir makes a bit of a difference (Linux, SSD, hot+cold), but not much, mostly for cold caches, for hot caches it is ~the same. Now, we already concluded that this doesn't affect Linux too much anyway, since it has optimizations for this. Benchmarks on OSX would be more interesting, I think, where verygreen saw these awfully long times for what's basically ls -R. Edit2: vvv Excellent, thanks!

[verygreen]

I'll do some measurements a bit later today and post them here

[verygreen]

I did some 1.0.1 Instrumentation so far and pasting it here for the record.

The test case was to create 1M randomly named files in a dir. Here's the code with whch it was created:

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

#define NUMBER 1000000

int main(int argc, char **argv)
{
    int i;
    char filename[PATH_MAX];

    if (argc != 2) {
        printf("Usage: Dir to create files in\n");
        return -1;
    }

    if (chdir(argv[1])) {
        perror("chdir");
        return -2;
    }

    for(i = 0 ; i <= NUMBER ; i++) {
        long rand;
        int fd;

        rand = random();

again:
        sprintf(filename, "%li\n", rand);
        fd = open(filename, O_CREAT|O_EXCL|O_WRONLY, 022);
        if ( fd == -1) {
            /* Must be a double hit, increase and try again */
            rand++;
            goto again;
        }

        write(fd, &rand, sizeof(rand) * 2); // some stack garbage too */
        close(fd);
    }

    return 0;
}

#### Testing on 7200 RPM single HDD, no other activity in the system or on it.
#### The node is i7 2600K, 32G RAM
[root@intelbox2 ~]# lvcreate -n TEST -L 100G slowdisk
  Logical volume "TEST" created.
[root@intelbox2 ~]# mkfs.ext4 /dev/slowdisk/TEST
mke2fs 1.42.13 (17-May-2015)
Creating filesystem with 26214400 4k blocks and 6553600 inodes
Filesystem UUID: 8c7042cb-fbdc-448e-9e31-227cd2883ab2
Superblock backups stored on blocks:
        32768, 98304, 163840, 229376, 294912, 819200, 884736, 1605632, 2654208,
        4096000, 7962624, 11239424, 20480000, 23887872

Allocating group tables: done
Writing inode tables: done
Creating journal (32768 blocks): done
Writing superblocks and filesystem accounting information: done
[root@intelbox2 ~]# mount /dev/slowdisk/TEST /mnt/
[root@intelbox2 ~]# mkdir /mnt/test
[root@intelbox2 ~]# time ./create-a-mil /mnt/test/

real    1m22.594s
user    0m0.422s
sys     0m13.195s
[root@intelbox2 ~]# time sync

real    2m5.392s
user    0m0.000s
sys     0m0.243s

[verygreen]

The 1.0.1 testing results:

### Testing with borg 1.0.1 release
[root@intelbox2 ~]# borg init --encryption=none /tmp/test-backup # tmpfs
[root@intelbox2 ~]# umount /mnt # Clear cache
[root@intelbox2 ~]# mount /dev/slowdisk/TEST /mnt/ 
[root@intelbox2 ~]# time borg create /tmp/test-backup::Initial /mnt/test

real    166m9.992s
user    6m33.515s
sys 1m43.802s
[root@intelbox2 ~]# time borg create /tmp/test-backup::HOT /mnt/test

real    1m25.694s
user    1m18.799s
sys 0m5.124s
[root@intelbox2 ~]# umount /mnt
[root@intelbox2 ~]# mount /dev/slowdisk/TEST /mnt/ 
[root@intelbox2 ~]# time borg create /tmp/test-backup::COLD /mnt/test

real    2m29.803s
user    1m23.781s
sys 0m9.970s
[root@intelbox2 ~]# time borg create /tmp/test-backup::HOT2 /mnt/test

real    1m26.764s
user    1m19.594s
sys 0m4.982s
[root@intelbox2 ~]# umount /mnt
[root@intelbox2 ~]# du -hs /tmp/test-backup 
293M    /tmp/test-backup

You can see how disproportionally large time it takes to create the archive. the time is spent thrashing the disk.

[verygreen]

I am running borg 1.0.1.dev6+ng95f9286 and it looks like something still incorrectly sorts the dentries not by inode, but by name.
I did an strace and here's what I am seeing:

lstat("/mnt/test/1019429875\n", {st_mode=S_IFREG, st_size=16, ...}) = 0
open("/mnt/test/1019429875\n", O_RDONLY|O_NOATIME|O_CLOEXEC) = 5
fstat(5, {st_mode=S_IFREG, st_size=16, ...}) = 0
fstat(5, {st_mode=S_IFREG, st_size=16, ...}) = 0
ioctl(5, TCGETS, 0x7ffc41602cd0)        = -1 ENOTTY (Inappropriate ioctl for device)
fstat(5, {st_mode=S_IFREG, st_size=16, ...}) = 0
lseek(5, 0, SEEK_CUR)                   = 0
read(5, "\363C\303<\0\0\0\00010194298", 8388608) = 16
fadvise64(5, 0, 16, POSIX_FADV_DONTNEED) = 0
close(5)                                = 0
llistxattr("/mnt/test/1019429875\n", NULL, 0) = 0
getxattr("/mnt/test/1019429875\n", "system.posix_acl_access", 0x0, 0) = -1 ENODATA (No data available)
getxattr("/mnt/test/1019429875\n", "system.posix_acl_default", 0x0, 0) = -1 ENODATA (No data available)
lstat("/mnt/test/1019430414\n", {st_mode=S_IFREG, st_size=16, ...}) = 0
open("/mnt/test/1019430414\n", O_RDONLY|O_NOATIME|O_CLOEXEC) = 5
fstat(5, {st_mode=S_IFREG, st_size=16, ...}) = 0
fstat(5, {st_mode=S_IFREG, st_size=16, ...}) = 0
ioctl(5, TCGETS, 0x7ffc41602cd0)        = -1 ENOTTY (Inappropriate ioctl for device)
fstat(5, {st_mode=S_IFREG, st_size=16, ...}) = 0
lseek(5, 0, SEEK_CUR)                   = 0
read(5, "\16F\303<\0\0\0\00010194304", 8388608) = 16
fadvise64(5, 0, 16, POSIX_FADV_DONTNEED) = 0
close(5)                                = 0
llistxattr("/mnt/test/1019430414\n", NULL, 0) = 0
getxattr("/mnt/test/1019430414\n", "system.posix_acl_access", 0x0, 0) = -1 ENODATA (No data available)
getxattr("/mnt/test/1019430414\n", "system.posix_acl_default", 0x0, 0) = -1 ENODATA (No data available)
lstat("/mnt/test/1019431109\n", {st_mode=S_IFREG, st_size=16, ...}) = 0
open("/mnt/test/1019431109\n", O_RDONLY|O_NOATIME|O_CLOEXEC) = 5
fstat(5, {st_mode=S_IFREG, st_size=16, ...}) = 0
fstat(5, {st_mode=S_IFREG, st_size=16, ...}) = 0
ioctl(5, TCGETS, 0x7ffc41602cd0)        = -1 ENOTTY (Inappropriate ioctl for device)
fstat(5, {st_mode=S_IFREG, st_size=16, ...}) = 0
lseek(5, 0, SEEK_CUR)                   = 0
read(5, "\305H\303<\0\0\0\00010194311", 8388608) = 16
fadvise64(5, 0, 16, POSIX_FADV_DONTNEED) = 0
close(5)                                = 0
llistxattr("/mnt/test/1019431109\n", NULL, 0) = 0
getxattr("/mnt/test/1019431109\n", "system.posix_acl_access", 0x0, 0) = -1 ENODATA (No data available)
getxattr("/mnt/test/1019431109\n", "system.posix_acl_default", 0x0, 0) = -1 ENODATA (No data available)
lstat("/mnt/test/1019433040\n", {st_mode=S_IFREG, st_size=16, ...}) = 0
open("/mnt/test/1019433040\n", O_RDONLY|O_NOATIME|O_CLOEXEC) = 5
fstat(5, {st_mode=S_IFREG, st_size=16, ...}) = 0
fstat(5, {st_mode=S_IFREG, st_size=16, ...}) = 0
ioctl(5, TCGETS, 0x7ffc41602cd0)        = -1 ENOTTY (Inappropriate ioctl for device)
fstat(5, {st_mode=S_IFREG, st_size=16, ...}) = 0
lseek(5, 0, SEEK_CUR)                   = 0
read(5, "PP\303<\0\0\0\00010194330", 8388608) = 16
fadvise64(5, 0, 16, POSIX_FADV_DONTNEED) = 0
close(5)                                = 0
llistxattr("/mnt/test/1019433040\n", NULL, 0) = 0
getxattr("/mnt/test/1019433040\n", "system.posix_acl_access", 0x0, 0) = -1 ENODATA (No data available)
getxattr("/mnt/test/1019433040\n", "system.posix_acl_default", 0x0, 0) = -1 ENODATA (No data available)

the names appear to be sorted by name, not by inode, for example:
[root@intelbox2 borg]# stat /mnt/test/1019430414*

  File: Б─≤/mnt/test/1019430414\nБ─≥
  Size: 16          Blocks: 8          IO Block: 4096   regular file
Device: fd0fh/64783d    Inode: 692616      Links: 1
Access: (0000/----------)  Uid: (    0/    root)   Gid: (    0/    root)
Access: 2016-04-14 13:40:12.447085161 -0400
Modify: 2016-04-14 13:40:12.447085161 -0400
Change: 2016-04-14 13:40:12.447085161 -0400
 Birth: -
[root@intelbox2 borg]# stat /mnt/test/1019429875*
  File: Б─≤/mnt/test/1019429875\nБ─≥
  Size: 16          Blocks: 8          IO Block: 4096   regular file
Device: fd0fh/64783d    Inode: 1173226     Links: 1
Access: (0000/----------)  Uid: (    0/    root)   Gid: (    0/    root)
Access: 2016-04-14 13:40:43.904431890 -0400
Modify: 2016-04-14 13:40:43.904431890 -0400
Change: 2016-04-14 13:40:43.904431890 -0400
 Birth: -