IO patterns in OCIS decomposed FS

[labkode]

This issue tracks IO patterns in the OCIS decomposed FS for optimisation.
Testing setup: https://owncloud.dev/ocis/getting-started/
Username for testing: einstein/relativity
Host machine: Centos 7
Version: Version: \n Compiled: 2022-06-15 00:00:00 +0000 UTC

The getxattr systemcall fails very often, same examples:

[pid 25116] 1655310943.001334 getxattr("/home/gonzalhu/.ocis/storage/users/spaces/4c/510ada-c86b-4815-8820-42cdf82c3d51/nodes/4c/51/0a/da/-c86b-4815-8820-42cdf82c3d51", "user.ocis.dtime", 0xc0032fa800, 1024) = -1 ENODATA (No data available) <0.000060>
[pid 25116] 1655310943.002241 getxattr("/home/gonzalhu/.ocis/storage/users/spaces/4c/510ada-c86b-4815-8820-42cdf82c3d51/nodes/4c/51/0a/da/-c86b-4815-8820-42cdf82c3d51", "user.ocis.dtime", 0xc007402400, 1024) = -1 ENODATA (No data available) <0.000054>
[pid 25116] 1655310943.002377 getxattr("/home/gonzalhu/.ocis/storage/users/spaces/4c/510ada-c86b-4815-8820-42cdf82c3d51/nodes/6a/a2/fa/4f/-65d2-4188-ab77-010bba9a473d", "user.ocis.tmtime", 0xc007402800, 1024) = -1 ENODATA (No data available) <0.000052>
[pid 25121] 1655310943.015012 getxattr("/home/gonzalhu/.ocis/storage/users/spaces/4c/510ada-c86b-4815-8820-42cdf82c3d51/nodes/4c/51/0a/da/-c86b-4815-8820-42cdf82c3d51", "user.ocis.dtime", 0xc0020c3000, 1024) = -1 ENODATA (No data available) <0.000147>
[pid 25122] 1655310944.256146 getxattr("/home/gonzalhu/.ocis/storage/users/spaces/f7/fbf8c8-139b-4376-b307-cf0a8c2d0d9c/nodes/f7/fb/f8/c8/-139b-4376-b307-cf0a8c2d0d9c", "user.ocis.dtime", 0xc000a1d800, 1024) = -1 ENODATA (No data available) <0.000108>
[pid 25122] 1655310944.256734 getxattr("/home/gonzalhu/.ocis/storage/users/spaces/f7/fbf8c8-139b-4376-b307-cf0a8c2d0d9c/nodes/f7/fb/f8/c8/-139b-4376-b307-cf0a8c2d0d9c", "user.ocis.cs3.ref", 0xc000a1dc00, 1024) = -1 ENODATA (No data available) <0.000121>
[pid 25122] 1655310944.257035 getxattr("/home/gonzalhu/.ocis/storage/users/spaces/f7/fbf8c8-139b-4376-b307-cf0a8c2d0d9c/nodes/f7/fb/f8/c8/-139b-4376-b307-cf0a8c2d0d9c", "user.ocis.treesize", 0xc003556000, 1024) = -1 ENODATA (No data available) <0.000156>
[pid 25122] 1655310944.257364 getxattr("/home/gonzalhu/.ocis/storage/users/spaces/f7/fbf8c8-139b-4376-b307-cf0a8c2d0d9c/nodes/f7/fb/f8/c8/-139b-4376-b307-cf0a8c2d0d9c", "user.ocis.tmtime", 0xc003556800, 1024) = -1 ENODATA (No data available) <0.000100>
[pid 25122] 1655310944.257628 getxattr("/home/gonzalhu/.ocis/storage/users/spaces/f7/fbf8c8-139b-4376-b307-cf0a8c2d0d9c/nodes/f7/fb/f8/c8/-139b-4376-b307-cf0a8c2d0d9c", "user.ocis.tmp.etag", 0xc003556c00, 1024) = -1 ENODATA (No data available) <0.000089>
[pid 25122] 1655310944.257876 getxattr("/home/gonzalhu/.ocis/storage/users/spaces/f7/fbf8c8-139b-4376-b307-cf0a8c2d0d9c/nodes/f7/fb/f8/c8/-139b-4376-b307-cf0a8c2d0d9c", "user.ocis.quota", 0xc003557000, 1024) = -1 ENODATA (No data available) <0.000120>
[pid 25117] 1655310944.263681 getxattr("/home/gonzalhu/.ocis/storage/users/spaces/f7/fbf8c8-139b-4376-b307-cf0a8c2d0d9c/nodes/f7/fb/f8/c8/-139b-4376-b307-cf0a8c2d0d9c", "user.ocis.dtime", 0xc002c37800, 1024) = -1 ENODATA (No data available) <0.000137>
[pid 25117] 1655310944.264340 getxattr("/home/gonzalhu/.ocis/storage/users/spaces/f7/fbf8c8-139b-4376-b307-cf0a8c2d0d9c/nodes/f7/fb/f8/c8/-139b-4376-b307-cf0a8c2d0d9c", "user.ocis.cs3.ref", 0xc002c37c00, 1024) = -1 ENODATA (No data available) <0.000100>
[pid 25117] 1655310944.264588 getxattr("/home/gonzalhu/.ocis/storage/users/spaces/f7/fbf8c8-139b-4376-b307-cf0a8c2d0d9c/nodes/f7/fb/f8/c8/-139b-4376-b307-cf0a8c2d0d9c", "user.ocis.treesize", 0xc003b54000, 1024) = -1 ENODATA (No data available) <0.000091>
[pid 25117] 1655310944.264813 getxattr("/home/gonzalhu/.ocis/storage/users/spaces/f7/fbf8c8-139b-4376-b307-cf0a8c2d0d9c/nodes/f7/fb/f8/c8/-139b-4376-b307-cf0a8c2d0d9c", "user.ocis.tmtime", 0xc003b54400, 1024) = -1 ENODATA (No data available) <0.000072>
[pid 25117] 1655310944.264985 getxattr("/home/gonzalhu/.ocis/storage/users/spaces/f7/fbf8c8-139b-4376-b307-cf0a8c2d0d9c/nodes/f7/fb/f8/c8/-139b-4376-b307-cf0a8c2d0d9c", "user.ocis.tmp.etag", 0xc003b54800, 1024) = -1 ENODATA (No data available) <0.000068>
[pid 25117] 1655310944.265165 getxattr("/home/gonzalhu/.ocis/storage/users/spaces/f7/fbf8c8-139b-4376-b307-cf0a8c2d0d9c/nodes/f7/fb/f8/c8/-139b-4376-b307-cf0a8c2d0d9c", "user.ocis.quota", 0xc003b54c00, 1024) = -1 ENODATA (No data available) <0.000062>
[pid 25756] 1655310944.479715 getxattr("/home/gonzalhu/.ocis/storage/users/spaces/f7/fbf8c8-139b-4376-b307-cf0a8c2d0d9c/nodes/f7/fb/f8/c8/-139b-4376-b307-cf0a8c2d0d9c", "user.ocis.dtime", 0xc003e5b400, 1024) = -1 ENODATA (No data available) <0.000067>
[pid 25756] 1655310944.480693 getxattr("/home/gonzalhu/.ocis/storage/users/spaces/f7/fbf8c8-139b-4376-b307-cf0a8c2d0d9c/nodes/f7/fb/f8/c8/-139b-4376-b307-cf0a8c2d0d9c", "user.ocis.dtime", 0xc00426c400, 1024) = -1 ENODATA (No data available) <0.000054>
[pid 25756] 1655310944.480832 getxattr("/home/gonzalhu/.ocis/storage/users/spaces/f7/fbf8c8-139b-4376-b307-cf0a8c2d0d9c/nodes/f7/fb/f8/c8/-139b-4376-b307-cf0a8c2d0d9c", "user.ocis.tmtime", 0xc00426c800, 1024) = -1 ENODATA (No data available) <0.000053>
[pid 25121] 1655310944.494343 getxattr("/home/gonzalhu/.ocis/storage/users/spaces/f7/fbf8c8-139b-4376-b307-cf0a8c2d0d9c/nodes/f7/fb/f8/c8/-139b-4376-b307-cf0a8c2d0d9c", "user.ocis.dtime", 0xc001c90800, 1024) = -1 ENODATA (No data available) <0.000069>
[pid 25117] 1655310944.632945 getxattr("/home/gonzalhu/.ocis/storage/users/spaces/f7/fbf8c8-139b-4376-b307-cf0a8c2d0d9c/nodes/f7/fb/f8/c8/-139b-4376-b307-cf0a8c2d0d9c", "user.ocis.dtime", 0xc001d20000, 1024) = -1 ENODATA (No data available) <0.000057>

Empty personal space

As a user I click on the "All files tab" from the web, the following number of requests are made:

[gonzalhu@iota dev]$ strace -s 1024 -p 25113 -f -e trace=file -c 2>&1
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 43.13    0.001547         111        14           openat
 42.01    0.001507          12       123        31 getxattr
  9.42    0.000338          15        22           listxattr
  3.79    0.000136          34         4           unlinkat
  1.20    0.000043          14         3           readlinkat
  0.45    0.000016           1        11           newfstatat
  0.00    0.000000           0         3           statfs
------ ----------- ----------- --------- --------- ----------------
100.00    0.003587                   180        31 total

Creating a folder in the empty personal space

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 40.30    0.004412         142        31         1 openat
 27.67    0.003030          19       160        40 getxattr
 11.94    0.001307         261         5           mkdirat
  6.96    0.000762          22        34         7 newfstatat
  4.92    0.000539          19        28           listxattr
  3.45    0.000378         378         1           symlinkat
  3.22    0.000353          59         6           unlinkat
  1.04    0.000114          29         4         2 readlinkat
  0.49    0.000054           8         7           setxattr
  0.00    0.000000           0         1         1 removexattr
------ ----------- ----------- --------- --------- ----------------
100.00    0.010949                   277        51 total

Listing the personal space that contains one folder

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 40.31    0.002312          15       155        31 getxattr
 35.83    0.002055         147        14           openat
  7.69    0.000441          15        30           listxattr
  6.92    0.000397          99         4           readlinkat
  5.77    0.000331          30        11           newfstatat
  3.49    0.000200          50         4           unlinkat
  0.00    0.000000           0         3           statfs
------ ----------- ----------- --------- --------- ----------------
100.00    0.005736                   221        31 total

Listing the personal space containing 10 folders

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 47.04    0.002578          10       266        75 getxattr
 33.67    0.001845         142        13           openat
  9.93    0.000544           9        58           listxattr
  4.38    0.000240           7        33           newfstatat
  2.48    0.000136          34         4           unlinkat
  2.06    0.000113           9        12           readlinkat
  0.44    0.000024           8         3           statfs
------ ----------- ----------- --------- --------- ----------------
100.00    0.005480                   389        75 total

Listing received shares panel (one share only)

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 51.35    0.000380           7        55        12 getxattr
 34.46    0.000255          64         4           openat
  7.70    0.000057           4        16           listxattr
  4.19    0.000031           3         9         1 newfstatat
  2.30    0.000017          17         1           unlinkat
------ ----------- ----------- --------- --------- ----------------
100.00    0.000740                    85        13 total

[labkode]

@dragotin @micbar this is a good starting point.
From this quick analysis I don't know if the explosion of the operations comes from the implementation of the filesystem (ocisfs) of from upper layers (gateway, storage provider, webdav, ...)

[butonic]

For eos most of the read xattrs are fetched with a single eos finfo. If you take a look at the xattr names: tmtime and treesize aro covered by the eos finfo. Measuring the number of xattr reads in decomposedfs and trying to inferring eos performance from it is wildly misleading, IMO.

Aggregating ListStorageSpace, Stat and GetPath into a single call seems to be the more fruitful approach: when making a PROPFIND /dav/space/{storageid$spaceid!opaqueid}/relative/path request we can improve performance in two ways:

1. get rid of the ListStorageSpaces call: ocdav: skip space lookup on spaces propfind #2977
2. add dedicated Name and Path properties to the CS3 ResourceInfo and use a field mask to indicate which property is requested. (the list shares call will profit from this even more)
3. add a Space property to the CS3 ResourceInfo so a space based Stat request can be routed based on the providerid and the space info can be returned if requested with a field mask.
4. use a field mask to make desktop client requests for the etag as cheap as possible. No need to build a full ResourceInfo, if all that is needed is the etag

[labkode]

@butonic for xattr is understandable, however there a dozens of stat calls, which they will affect EOS.

[micbar]

2. add dedicated Name and Path properties to the CS3 ResourceInfo and use a field mask to indicate which property is requested. (the list shares call will profit from this even more)
3. add a Space property to the CS3 ResourceInfo so a space based Stat request can be routed based on the providerid and the space info can be returned if requested with a field mask.
4. use a field mask to make desktop client requests for the etag as cheap as possible. No need to build a full ResourceInfo, if all that is needed is the etag

CS3Api Change in cs3org/cs3apis#173

[labkode]

Work in progress.

I suggest you do a profiling of the previous scenarios on edge to compare to baseline in master.
The profiling will help to identify where the bottlenecks are, to remove the implementation of driver aside.

[labkode]

Work in progress.