Slow start of a systemd unit implemented in .NET

5 min read Original article ↗

In this post I would like to describe my recent experience of troubleshooting a slow-starting systemd unit implemented in .NET. While Linux troubleshooting is still new territory for me, I am gradually learning new tools and techniques. I wanted to share some of my discoveries in the hope that you will find them interesting 😊

The faulty application was a usual worker service (dotnet new worker), running under a system account (created with useradd –system myservice) and integrated with systemd through the Microsoft.Extensions.Hosting.Systemd library. Its unit file is straightfoward:

[Unit]
Description=My service

[Service]
Type=notify
User=myservice
ExecStart=/usr/local/bin/myservice

[Install]
WantedBy=multi-user.target

The app was published using NativeAOT, so deployment only required copying the myservice binary to the /usr/local/bin folder. While the application launched instantly when executed from the build directory, running it as a service introduced a multi-second startup delay:

time sudo systemctl start test-service
________________________________________________________
Executed in    9.15 secs      fish           external
   usr time   27.59 millis    1.74 millis   25.86 millis
   sys time   26.31 millis    0.12 millis   26.19 millis

Interestingly, after the initial startup delay, the service operated normally. Since the delay was consistent across service restarts, I needed to investigate its cause.

Using bpftrace to profile the service start

Debugging system service startup is typically challenging. Initially, I attempted to add dotnet trace to the ExceStart= systemd setting, but it did not seem to work. Instead, I decided to use bpftrace, a powerful tool for interacting with Linux’s eBPF toolkit. While I’m still learning its syntax and features, I’m thoroughly impressed and expect it to become my go-to tracing tool on Linux. The profiling command I used for the service startup was:

sudo bpftrace -o myservice-trace.out -q -e 'profile:hz:99 / comm == "myservice" / { @[ustack()] = count(); }'

It enables the user (@[ustack()]) stack collection at 99 Hertz (profile:hz:99), setting a filter on a process name (/ comm == “myservice” /). If you are unfamiliar with bpftrace syntax, have a look at the awesome one-liners tutorial. The command generated a myservice-trace.out file containing plaintext call stack dumps. Thanks to Brendan Gregg’s flame graph scripts, I could easily transform these stack traces into a flame graph:

stackcollapse-bpftrace.pl myservice-trace.out > myservice-trace.processed
flamegraph.pl myservice-trace.processed > myservice-trace.svg

The only problem was that .NET stacks were not resolved (however, the flame graph proved that the problem lies somewhere in managed stacks).

Resolving .NET stacks in bpftrace output

Before we focus on .NET, let me briefly explain how bpftrace resolves native call stacks. Most Linux distributions nowadays provide debuginfod URLs for downloading debug symbol files for the officially available packages. If you have a Windows background, it is very similar to Microsoft public symbols servers, except it’s better since all the symbols contain private information and links to the source files! Even if you haven’t configured them explicitly, there is a good chance the DEBUGINFOD_URLS variable is already set on your system. For example, on my EndevourOS system, it was set to https://debuginfod.archlinux.org by the core/libelf package. Note that the DEBUGINFOD_URLS variable might not be passed to the sudo command, breaking symbol resolution for tools requiring root privileges (bpftrace is one of them). To solve that problem, you may create a debuginfod text file in the /etc/sudoers.d folder with the following content:

## Preserve debuginfod settings for all apps
Defaults env_keep += "DEBUGINFOD_URLS"

When bpftrace (or any other debugging tool supporting debuginfod) resolves the call stacks, it downloads the debug symbol files and places them in a local cache, located at ~/.cache/debuginfod_client. The debug symbol files are grouped into folders with names equal to their respective build IDs. A build ID is a unique identifier added in the .note.gnu.build-id section of the ELF file. We can read this identifier with the file command. In my case, the file command showed the following information:

/usr/local/bin/myservice: ELF 64-bit LSB pie executable, x86-64, version 1 (SYSV), dynamically linked, interpreter /lib64/ld-linux-x86-64.so.2, BuildID[sha1]=cc8f0380b33a86c960bf9f5065f9575e6d4da016, for GNU/Linux 4.4.0, strippe

When we publish a .NET application using NativeAOT, the compiler produces an application binary file and a debug symbols file, in my case, myservice and myservice.dbg. We may publish the dbg file to our debuginfod symbol server (if we have one). In my case, I just copied the file directly into the cache folder (we need to use the root user cache since bpftrace requires root privileges):

sudo cp ./myservice.dbg /root/.cache/debuginfod_client/cc8f0380b33a86c960bf9f5065f9575e6d4da016/debuginfo

Then I recorded the trace again, processed it with flame graph tools, and the result flame graph was much clearer:

Identifying the problem and solving it

While investigating the source code (HostApplicationBuilder.cs, HostingHostBuilderExtensions.cs), I discovered that the host builder for worker services (and ASP.NET applications) automatically creates inotify watchers for appsettings JSON files across all the directories in the working directory tree. Since systemd defaults to using the root folder (/) as the working directory for its units, my service was inadvertently creating watchers for every accessible folder in the file system!

There are two ways to resolve this issue:

  • Set a specific working folder for our service using the WorkingDirectory= setting in the systemd unit file, which will limit the scope of file watchers.
  • Disable file watchers completely by setting the DOTNET_hostBuilder:reloadConfigOnChange environment variable to false (systemd does not like ‘:’ so I needed to use ‘__’) or use the appsettings file to configure this setting.

I chose the second approach and my final service unit file looked as follows

[Unit]
Description=My service

[Service]
Type=notify
User=myservice
Environment="DOTNET_hostBuilder__reloadConfigOnChange=false"
ExecStart=/usr/local/bin/myservice

[Install]
WantedBy=multi-user.target

And the service started in milliseconds 🙂

systemctl daemon-reload
time sudo systemctl start test-service
________________________________________________________
Executed in  196.91 millis    fish           external
   usr time   15.42 millis  863.00 micros   14.55 millis
   sys time    8.35 millis    0.00 micros    8.35 millis