Large number of filesystem operations when idle

#1

For my workspace storage I’m using Azure Files, which charges for transactions such as read, write, list, etc. I’m seeing thousands of transactions per minute when the workspace is open, but not being used. Is there something in Theia that might cause this?

Note that this is using the default theia docker image (theiaide/theia).

Here is some additional info I found in our metrics. This shows number of transactions by operation type (with only one Theia instance running). It shows that the vast majority of operations are metadata-specific (Create, Close, & QueryInfo), and not read/write:

image
image692×368 11.2 KB

(each bar on the x-axis is one minute)

This is with a single 60-byte file in the workspace directory.

#3

What does it mean to Create and Close here?

#4

@bendavis that seems way excessive for a 1-file workspace. Any idea where these operations originate?

One idea: depending on how the app is built, extensions that are to be included with the app may need to be unpacked at runtime, in directory /tmp/vscode-unpacked. This may mean a temporary I/O load at application startup, including creation of a relatively large number of files. It would not happen again if the workspace is switched or re-opened.

#5

I confirmed it’s not the case for theiaide/theia: the extensions are bundled already unpacked.

#6

Can you explain a bit how these metrics are collected and what they mean?

This is with a single 60-byte file in the workspace directory.

Can you share the file type? Was the file open? If so it could be a language-specific extension kicking-in and e.g. fetching some required dependencies, saving them to disk. e.g. I think vscode-clangd may attempt to fetch clangd, if not present.

#7

@marcdumais-work @marechal-p Here is some more information on the transaction types. Note that the transactions in question are via a SMB mount.

image
image1004×513 56.8 KB

Can you explain a bit how these metrics are collected and what they mean?

These metrics are collected by Azure for monitoring and billing purposes. The graphic pasted above should provide more info, but the main issue is the large number of Create, Close, and QueryInfo operations. I can do more research as to what these translate to in terms of linux filesystem, but regardless there is some kind of excessive work being done with the filesystem when Theia is in use.

I also did baseline tests on a simple alpine-node container with a basic nodejs express “hello world” server. This did not cause any noticable activity with the filesystem.

I also tested starting up theia vs. loading it in the browser. The activity only started once I opened Theia in the browser.

Can you share the file type? Was the file open? If so it could be a language-specific extension kicking-in and e.g. fetching some required dependencies, saving them to disk. e.g. I think vscode-clangd may attempt to fetch clangd , if not present.

This was tested using an .html file with some very basic HTML markup. This file was open when these metrics were recorded.

#8

Thanks for providing details @bendavis
Do you have a way to access the Theia app backend log? It’s the container’s entrypoint, so it’s probably also the container’s log. I wonder if there might be clues at to what’s happening. Please also check in the frontend app, in the dev tools’s console, for any suspicious errors or warnings.

In my experience, this can introduce nothing but problems, when used in a Linux context. E.g. permissions not quite mapping well. Do you know if the whole container’s storage is on that SMB mount or only the workspace? Would file operations in /tmp or writing system logs in /var/log count towards these metrics? Would the file reads required to start the Theia application count?

I do not know if the inotify kernel-level file-watcher mechanism we use on Linux, through the nsfw library, works well on a SMB mount.

A theory:
In Theia apps, we use inotify to watch the workspace folder, recursively. But there a few important config files that are watched individually, like settings.json on the current workspace and in the user’s home ~/.theia/settings.json I think. As well task.json and maybe a few others. We rely on the watching mechanism to re-rad these files, when notified they were modified.

IIRC, with nsfw on Linux, individually-watched files do not rely on inotify and instead use a poling mechanism to detect changes or deletion. If we have let’s say 5 of these files watched by polling, each polled e.g. every second, that’s at least ~300 operations a minute. It’s quite possible that e.g. one poll operation, e.g. using the “stat” system call, needs to be translated into multiple SMB operations, each poll then potentially triggering multiples of the listed counters. If hypothetically 4 NFS counters were triggered, on average, each times a nsfw poll happens, we then get close to what you’re observing.

#9

It means the HTML language server was probably active, potentially contributing to the reported file operations. This feature is provided by the HTML Language Features built-in extension

#10

test: not sure on Alpine but on some linux distros I think tail -f uses one inotify to detect changes to the file. So something like the following might be a test to replicate. Adapt to your workspace path / HTML file name. Ideally do it in a fresh workspace where you have never opened that file in the Theia app:

tail -f <myworkspace>/myfile.html
#11

@marcdumais-work Thanks so much for your thoughts on this and for your suggestions! I will have to do some more in-depth testing to see if I can get to the bottom of this.

Regarding the SMB mount, it is only used for the project workspace files. What I’m doing is opening Theia, and going to “open workspace” and opening a directory under SMB mount under /mnt. It’s only then that I see the excessive transactions in our metrics.

I wasn’t aware that nfsw used polling for individual files, I assumed it used inotify. I can do more digging to see if this is contributing to the issue.

#12

Also, I should mention I also ran a container with a test python script that does use inotify to monitor file changes in the mounted SMB dir, and that did not seem to cause excessive transactions.

#13

@marcdumais-work I did some more testing and found that I was still getting over 1,000 operations per minute even with no files whatsoever in the workspace.

Luckily I was finally able to capture detailed log information at the transaction level:

image
image1626×808 181 KB

What I’m seeing is operations on the following paths:

  • [workspace root]/
  • [workspace root]/.theia
  • [workspace root]/.vscode

The SMB API operations involved are Create, Close, and QueryInfo, which are all considered “metadata” operations (these are not basic read/writes).

It looks like theia is trying to create .theia and .vscode directories under the workspace path, but failing (for whatever reason).

I’m not sure why .theia and .vscode directories are even being created/accessed here, as I thought these were supposed to exist under $HOME, not the workspace directory.

#14

Theia and VS Code both support workspace-level configuration files. e.g. Theia’s repo .vscode folder.

I also see that the different Create operations are counted as 0? Does that mean that those are not billed? At any rate what your capture shows here is interesting.

#15

@marechal-p I don’t know why they’re being marked as 0, but the large frequency of these operations is reason enough to make me want to find the source of this.

I’m happy to troubleshoot this by hacking/building the main repo, but can anyone tell me a good place to start looking? Is configuration writing done in core or some other package?

#16

Could it be the watchers, polling for eventual existance of .theia/settings.json, .vscode/settings.json, theia/task.json and so on?

#17

@marechal-p do you remember in which use-case and how the polling setup that we saw for individual files worked? Was it part of nsfw or Theia’s watcher ifrastructure? I remember we were surprised about it but not the details.

#18

I think a load of ~1000 filesystem operations a minute, though it looks like a lot, is unlikely to be noticed by Theia developers on their laptop during development/tests, unless one watches very closely. Specially if a big proportion is about querying metadata rather than reads/writes.

I’m happy to troubleshoot this by hacking/building the main repo, but can anyone tell me a good place to start looking? Is configuration writing done in core or some other package?

Maybe disable file watching or creation of watchers for individual config files such as settings.json. @marechal-p any quick idea that would silently disable watchers completely or maybe only for config files? This could at least permit to test the theory that the observed load is watcher-related.

#19

Maybe this: https://github.com/Axosoft/nsfw/blob/master/js/src/index.js#L6

Edit: there’s apparently a fs.stat() each poll:

function NSFWFilePoller(watchPath, eventCallback, debounceMS) {
  const { CREATED, DELETED, MODIFIED } = nsfw.actions;
  const directory = path.dirname(watchPath);
  const file = path.basename(watchPath);

  let fileStatus;
  let filePollerInterval;

  const getStatus = async () => {
    try {
      const status = await fs.stat(watchPath);
#20

I have a suggestion of a refined test, that could be instructive. You might try to make a quick script that watches for a few specific files, that do not yet exist. I suggest mimicking the theia case, and e.g. watch for arbitrary files under a folder that does not (yet) exist. e.g.:

./test/file1 ,
./test/file2 ,
[...]

where ./test does not exist. 4-6 or so files being watched in parallel sound about right to reproduce what we have in Theia apps I think, watching for important configuration files.

#21

@marcdumais-work I created a simple test script:

const nsfw = require('nsfw');

async function run() {
  nsfw('/tmp/foobar', events => console.log(events))
    .catch(error => console.error(error));

  while (true) {
    await new Promise(r => setTimeout(r, 1000));
  }
}

run().catch(err => console.log(err));

It seems nsfw does not allow watching paths that do not exist. If you try to call nsfw with a non-existent path, it throws an error:

$ node test.js
Error: Path must be a valid path to a file or a directory.

So, it seems the issue can’t be caused by nsfw if those files in fact do not exist?