naiveBuildDirectory / (*localDirectory).Link performance problems

[Links2004]

Hi,

our bb-worker currently spends more time handling the files inputs then executing any actions.
example:

all the input file are already in the local cache, but the Linking seams to take for ever.
after some debugging using pprof we noticed that most of the time spend is spent within the garbage collection:

looks like that the linking of files creates a lot of objects, on example I found is here:
https://github.com/buildbarn/bb-storage/blob/3991d6ebefb4cfc7c1956caaba5a28d1b2eca927/pkg/filesystem/local_directory_unix.go#L401

is there anything we can do to optimize the Linking / GetFile code path to not use that many objects and as a result get faster?

we tried to increase the inputDownloadConcurrency but this is basically only result in more and longer garbage collection runs.
setting GOGC=off did only delay the problem until the memory is full, so it look like some code need optimizing to reduce copies and object creation.

Markus Sattler, Mercedes-Benz Tech Innovation GmbH

Provider Information

[EdSchouten]

I think we should be careful how we interpret these results. It's easy to think "this function is slow, because it's doing lots of garbage collection". But at the end this calls the linkat() system call. The question is, how does that show up in this flame graph? Does it actually get accounted as "CPU usage"? To me it seems odd that the input root linking spends more time in the garbage collector than in the linkat() system call.

[EdSchouten]

What happens if we make a simple change like this?

diff --git pkg/filesystem/local_directory_unix.go pkg/filesystem/local_directory_unix.go
index 4d77771..4bcbd63 100644
--- pkg/filesystem/local_directory_unix.go
+++ pkg/filesystem/local_directory_unix.go
@@ -155,7 +155,7 @@ func (d *localDirectory) OpenWrite(name path.Component, creationMode CreationMod

 func (d *localDirectory) Link(oldName path.Component, newDirectory Directory, newName path.Component) error {
        defer runtime.KeepAlive(d)
-       return newDirectory.Apply(localDirectoryLink{
+       return newDirectory.Apply(&localDirectoryLink{
                oldFD:   d.fd,
                oldName: oldName,
                newName: newName,
@@ -492,7 +492,7 @@ type localDirectoryClonefile struct {

 func (d *localDirectory) Apply(arg interface{}) error {
        switch a := arg.(type) {
-       case localDirectoryLink:
+       case *localDirectoryLink:
                defer runtime.KeepAlive(d)
                return unix.Linkat(a.oldFD, a.oldName.String(), d.fd, a.newName.String(), 0)
        case localDirectoryRename:

Kind of odd if it made a big difference, but worth trying regardless.

[Links2004]

I am currently looking into a way to easy test changes, doing changes in production is not straight forward and risky.
Our Dev and Int env does not have the load to easy show the problem.

On Idea is to, may combine it with no objects at all for the most likely case, e.g.:

 func (d *localDirectory) Link(oldName path.Component, newDirectory Directory, newName path.Component) error {
        defer runtime.KeepAlive(d)
+       // reduce object creation on heap if possible
+       if newDir, ok := newDirectory.(*localDirectory); ok {
+               return unix.Linkat(d.fd, oldName.String(), newDir.fd, newName.String(), 0)
+       }
        return newDirectory.Apply(localDirectoryLink{
                oldFD:   d.fd,
                oldName: oldName,

the graph was generated via go tool pprof --http=:8081 http://127.0.0.1:9980/debug/pprof/profile.
the linkat syscall is shown as ~2% while the runtime.convT is at 33%, while the runtime.gcBgMarkWorker is another 34%.

[EdSchouten]

So unfortunately we allow instances of Directory to be wrapped (see LazyDirectory). That means that the double dispatch mechanism we have right now cannot be trivially eliminated.

[EdSchouten]

Yeah, I get that the linkat sys call is shown as ~2%. But when does the Go runtime start/stop counting? Is the time spent in the kernel also part of that red bar? Or does the red bar only cover the time spent inside the system call wrapper in user space, outside of the system call?

[Links2004]

the red bars (runtime.convT) gc + convT happen before the exec of the Apply function,
e.g. the object creation of localDirectoryLink which triggers the gc.

[EdSchouten]

I think there is some miscommunication here. Let me reiterate my question:

Does the flame graph above represent the amount of CPU time the process spends overall, or does it only represent the time spent in userspace?

You could argue that it's the overall time, because there is a Syscall6 in there. But that's only half the truth. That Syscall6 function also has some preamble/postprocessing in it that runs in user space. So even if we see it appear in a flame graph, that doesn't necessarily imply that the process was running in kernel space at that point in time.

The reason I'm asking this question: if this only measures the time in user space, then that doesn't imply that the garbage collector is actually the bottleneck here. Maybe you're just spending an awful amount of time in kernel space doing linkat() system calls.

[Links2004]

good question, did look in to it from a diffrent angle and build a simple test case to measure how much memory / mallocs are used.

results:

Initial memory usage: 1.70 MB (58121 objects)
Memory usage after 10000 Link calls: 10.09 MB (388121 objects)
Memory increase: 8.39 MB (330000 objects)
Memory per Link call: 880.00 B (33 objects)

using pointers for apply or not did not make any difference.
this numbers add up fast since remote execution is running a lot of actions with a lot of Link calls.

quick and dirty code:

func TestLazyDirectoryLinkMemory(t *testing.T) {
	tmpPath := "/mnt/tmp" // tmpfs mount point

	buildDirectoryPath, scopeWalker := path.EmptyBuilder.Join(path.NewAbsoluteScopeWalker(path.VoidComponentWalker))
	if err := path.Resolve(path.LocalFormat.NewParser(tmpPath), scopeWalker); err != nil {
		require.NoError(t, err, "Failed to resolve build directory %#v", tmpPath)
	}

	directory := re_filesystem.NewLazyDirectory(func() (filesystem.DirectoryCloser, error) {
		return filesystem.NewLocalDirectory(buildDirectoryPath)
	})
/*
	directory, err := filesystem.NewLocalDirectory(buildDirectoryPath)
	require.NoError(t, err, "Failed to create local directory")
	defer directory.Close()
*/

	// start with a clean directory
	directory.RemoveAllChildren()

	src := path.MustNewComponent("src")
	fw, err := directory.OpenWrite(src, filesystem.CreateReuse(0o555))
	require.NoError(t, err, "Failed to open file for writing")
	_, err = fw.WriteAt([]byte("hello world\n"), 0)
	require.NoError(t, err, "Failed to write to file")
	require.NoError(t, fw.Close(), "Failed to close file")

	testCount := uint64(10000)

	dests := make([]path.Component, testCount)
	for i := uint64(0); i < testCount; i++ {
		dests[i] = path.MustNewComponent(fmt.Sprintf("dest%d", i))
	}

	// disable the gabege collector
	runtime.GC()
	runtime.MemProfileRate = 0
	debug.SetGCPercent(-1)
	debug.SetMemoryLimit(1024 * 1024 * 1024)

	// get current memory usage, so that we can check that it does not grow after the Link calls
	var initialMem runtime.MemStats
	runtime.ReadMemStats(&initialMem)

	// run the Link 10000 times and check that memory usage does not grow
	for i := uint64(0); i < testCount; i++ {
		directory.Link(src, directory, dests[i])
	}

	// check that memory usage does not grow after the Link calls
	var afterMem runtime.MemStats
	runtime.ReadMemStats(&afterMem)

	memIncrease := afterMem.Alloc - initialMem.Alloc
	objIncrease := afterMem.Mallocs - initialMem.Mallocs

	fmt.Printf("Initial memory usage: %.2f MB (%d objects)\n", float64(initialMem.Alloc)/1024.0/1024.0, initialMem.Mallocs)
	fmt.Printf("Memory usage after %d Link calls: %.2f MB (%d objects)\n", testCount, float64(afterMem.Alloc)/1024.0/1024.0, afterMem.Mallocs)
	fmt.Printf("Memory per Link call: %.2f B (%d objects)\n", float64(memIncrease)/float64(testCount), objIncrease/testCount)

	require.LessOrEqual(t, memIncrease, uint64(1024), "Memory increase: %.2f MB", float64(memIncrease)/1024.0/1024.0)
	require.LessOrEqual(t, objIncrease, uint64(1024), "Object increase: %d", objIncrease)
}

on question in my mind is if the lazyDirectory is needed for the non fuse cases, we may make it optional to allow optimization for the local / native case?

simply removing lazyDirectory ends up with:

Initial memory usage: 1.71 MB (58106 objects)
Memory usage after 10000 Link calls: 2.32 MB (88107 objects)
Memory increase: 0.61 MB (30001 objects)
Memory per Link call: 64.00 B (3 objects)

and bypassing the Apply via newDir, ok := newDirectory.(*localDirectory); ok gives:

Initial memory usage: 1.72 MB (58109 objects)
Memory usage after 10000 Link calls: 1.87 MB (78110 objects)
Memory increase: 0.15 MB (20001 objects)
Memory per Link call: 16.00 B (2 objects)

which is over 10x better then lazyDirectory.

happy to here ideas.

[EdSchouten]

Memory per Link call: 64.00 B (3 objects)

How does this compare to the amount of memory allocated inside of the Linux kernel when executing the linkat() system call?

[Links2004]

we are talking user space only here, the kernel memory is nothing we can optimize or easy see here.
Memory per Link call means this call here:

directory.Link(src, directory, dests[i])

[EdSchouten]

we are talking user space only here, the kernel memory is nothing we can optimize or easy see here.

Exactly. And if the kernel is already allocating 10 times as much memory and spends 10 times as many cycles, then why bother making any code changes on our end?

[Links2004]

the lazyDirectory is the bottleneck not the kernel.
to me it looks like that calling NewLocalDirectory for every operation of lazyDirectory is creating the big overhead, and this can be avoided in multiple ways.

• bypass lazyDirectory when not needed (config option, most performance)
• cache the directoryOpener result and only call the opener when really needed (more overhead but better then now)

and then there is the fact the we can bypass Apply for more speed in the non lazyDirectory case.

we can be upto 33% faster without any kernel changes, and I do not see why its good to not look in to it.

[EdSchouten]

lazyDirectory is only used by bb_runner which hardly does any file system intensive I/O. And even there it's only used for the top-level directory.

[Links2004]

as far as i understand its used to manage the buildDirectory which is all the preparing of the build dirs for each action?
and the build dirs itself are use Link (same inode) to the cache dir.
so all files/dirs that a needed for the action are handled by lazyDirectory?

[EdSchouten]

lazyDirectory is only used by bb_runner to access the build directory's top-level directory. It's there to ensure that bb_runner doesn't constantly have a file descriptor for the directory, even when the worker/runner are idle. That way bb_runner will not attempt to open the build directory before the worker has set up its virtual file system (if applicable).