Che: Che not responding after file operations (creation, deletion, renaming)

[emvau]

File operations in general make the Eclipse Che (Chrome tab) not respond from about 30sec up to 5mins max. E.g. when creating a new text file, I am able to write for about 10sec until the IDE freezes.
After several chrome "... not responding"-messages and "Wait" clicks, the IDE gets accessible again.

Dev tools show this:

It may be a che config issue on my side, but then, I do not know where to change this.

Reproduction Steps:

1. Start Workspace
2. Navigate to file in Project Explorer
3. Delete/Rename/Create a file

Che version: 5.2.0-SNAPSHOT (also occured with 5.0.1)

OS and version: Ubuntu 16.04.1 LTS

Docker version: 1.12.5 (client & server)

Che cli.log output: (dns name of the server got obfuscated)

`Sat Jan 21 14:11:45 UTC 2017
INFO: (che cli): Checking network... (hint: '--fast' skips version, network, and nightly checks)
/usr/bin/curl "-I -k dockerhub.com -s -o /dev/null --write-out %{http_code}"
INFO: (che cli): Loading cli...
DEBUG: docker_run
DEBUG: is_boot2docker
DEBUG: update_image
INFO: (che download): Pulling image eclipse/che:nightly

docker pull eclipse/che:nightly >> "/data/cli.log" 2>&1

DEBUG: is_initialized
DEBUG: cli_parse
DEBUG: cmd_start
DEBUG: is_initialized
DEBUG: is_docker_for_mac
docker inspect -f '{{.Id}}' che
DEBUG: is_initialized
DEBUG: is_initialized
WARN: (che init): 'nightly' installations cannot be upgraded to non-nightly versions
INFO: (che cli): Checking registry for version 'nightly' images
eval IMAGE_PUPPET=puppet/puppet-agent-alpine:4.6.2
eval IMAGE_REGISTRY=registry:2.5.0
eval IMAGE_INIT=eclipse/che-init:nightly
eval IMAGE_CHE=eclipse/che-server:nightly
DEBUG: update_image_if_not_found
INFO: (che download): Checking for image 'puppet/puppet-agent-alpine:4.6.2'...
found
DEBUG: update_image_if_not_found
INFO: (che download): Checking for image 'registry:2.5.0'...
found
DEBUG: update_image_if_not_found
INFO: (che download): Checking for image 'eclipse/che-init:nightly'...
not found
DEBUG: update_image
INFO: (che download): Pulling image eclipse/che-init:nightly

docker pull eclipse/che-init:nightly >> "/data/cli.log" 2>&1

DEBUG: update_image_if_not_found
INFO: (che download): Checking for image 'eclipse/che-server:nightly'...
not found
DEBUG: update_image
INFO: (che download): Pulling image eclipse/che-server:nightly

docker pull eclipse/che-server:nightly >> "/data/cli.log" 2>&1

INFO: (che init): Installing configuration and bootstrap variables:
mkdir -p "/data"
mkdir -p "/data/instance"
docker_run -v /srv/che-nightly:/copy eclipse/che-init:nightly
DEBUG: docker_run
INFO: (che init): CHE_HOST=172.31.33.155
INFO: (che init): CHE_VERSION=nightly
INFO: (che init): CHE_CONFIG=/srv/che-nightly
INFO: (che init): CHE_INSTANCE=/srv/che-nightly/instance
INFO: (che config): Generating che configuration...
DEBUG: generate_configuration_with_puppet
DEBUG: is_docker_for_windows
docker_run --env-file="/data/che.env" --env-file=/version/nightly/images -v "/srv/che-nightly/instance":/opt/che:rw -e "CHE_ENV_FILE=/srv/che-nightly/instance/config/che.env" -e "CHE_CONTAINER_ROOT=/data" -e "CHE_ENVIRONMENT=production" -e "CHE_CONFIG=/srv/che-nightly/instance" -e "CHE_INSTANCE=/srv/che-nightly/instance" -e "CHE_REPO=off" --entrypoint=/usr/bin/puppet eclipse/che-init:nightly apply --modulepath /etc/puppet/modules/ /etc/puppet/manifests/ --show_diff >> "/data/cli.log"
DEBUG: docker_run
Notice: Compiled catalog for 0f145523f469.us-west-2.compute.internal in environment production in 0.19 seconds
Notice: /Stage[main]/Base/File[/opt/che/data]/ensure: created
Notice: /Stage[main]/Base/File[/opt/che/config]/ensure: created
Notice: /Stage[main]/Base/File[/opt/che/logs]/ensure: created
Notice: /Stage[main]/Base/File[/opt/che/templates]/ensure: created
Notice: /Stage[main]/Base/File[/opt/che/stacks]/ensure: created
Notice: /Stage[main]/Che/File[/opt/che/config/che.env]/ensure: defined content as '{md5}0d18895b7b3d8a941e874b927a792185'
Notice: /Stage[main]/Compose/Compose::Generate_compose_file[docker-compose-container.yml]/File[/opt/che/docker-compose-container.yml]/ensure: defined content as '{md5}e91b4cb17856866e4a21786454ccd295'
Notice: /Stage[main]/Compose/Compose::Generate_compose_file[docker-compose.yml]/File[/opt/che/docker-compose.yml]/ensure: defined content as '{md5}498a74860e395e366b33a4040c86c0ad'
Notice: Applied catalog in 0.05 seconds
INFO: (che config): Customizing docker-compose for running in a container
INFO: (che start): Preflight checks
DEBUG: port_open
port 8080 (http): [AVAILABLE]
DEBUG: port_open

INFO: (che start): Starting containers...
docker_compose --file="/data/instance/docker-compose-container.yml" -p="che" up -d >> "/data/cli.log" 2>&1
DEBUG: docker_compose
DEBUG: docker_run
Recreating che
docker inspect -f '{{.Id}}' che
INFO: (che start): Services booting...
INFO: (che start): Server logs at "docker logs -f che"
DEBUG: docker_compose
DEBUG: docker_run
DEBUG: Container with id b98a4716ed40 is matching che service
DEBUG: Running state of container b98a4716ed40 is true
/usr/bin/curl "-I -k 172.31.33.155:8080/api/ -s -o /dev/null --write-out %{http_code}"
000
sleep 2
/usr/bin/curl "-I -k 172.31.33.155:8080/api/ -s -o /dev/null --write-out %{http_code}"
200
DEBUG: docker_compose
DEBUG: docker_run
DEBUG: Container with id b98a4716ed40 is matching che service
DEBUG: Running state of container b98a4716ed40 is true
/usr/bin/curl "-I -k 172.31.33.155:8080/api/ -s -o /dev/null --write-out %{http_code}"
200
DEBUG: is_initialized
DEBUG: docker_run
DEBUG: is_docker_for_mac
INFO: (che start): Booted and reachable
DEBUG: is_initialized
INFO: (che start): Ver: nightly
INFO: (che start): Use: http://172.31.33.155:8080
INFO: (che start): API: http://172.31.33.155:8080/swagger
Sat Jan 21 14:34:55 UTC 2017
INFO: (che cli): Checking network... (hint: '--fast' skips version, network, and nightly checks)
/usr/bin/curl "-I -k dockerhub.com -s -o /dev/null --write-out %{http_code}"
INFO: (che cli): Loading cli...
DEBUG: docker_run
DEBUG: is_boot2docker
DEBUG: update_image
INFO: (che download): Pulling image eclipse/che:nightly

docker pull eclipse/che:nightly >> "/data/cli.log" 2>&1

DEBUG: is_initialized
DEBUG: is_initialized
DEBUG: is_initialized
DEBUG: cli_parse
DEBUG: cmd_start
DEBUG: is_initialized
INFO: (che cli): Checking registry for version 'nightly' images
eval IMAGE_PUPPET=puppet/puppet-agent-alpine:4.6.2
eval IMAGE_REGISTRY=registry:2.5.0
eval IMAGE_INIT=eclipse/che-init:nightly
eval IMAGE_CHE=eclipse/che-server:nightly
DEBUG: update_image
INFO: (che download): Pulling image puppet/puppet-agent-alpine:4.6.2

docker pull puppet/puppet-agent-alpine:4.6.2 >> "/data/cli.log" 2>&1

DEBUG: update_image
INFO: (che download): Pulling image registry:2.5.0

docker pull registry:2.5.0 >> "/data/cli.log" 2>&1

DEBUG: update_image
INFO: (che download): Pulling image eclipse/che-init:nightly

docker pull eclipse/che-init:nightly >> "/data/cli.log" 2>&1

DEBUG: update_image
INFO: (che download): Pulling image eclipse/che-server:nightly

docker pull eclipse/che-server:nightly >> "/data/cli.log" 2>&1

INFO: (che config): Generating che configuration...
DEBUG: generate_configuration_with_puppet
DEBUG: is_docker_for_windows
docker_run --env-file="/data/che.env" --env-file=/version/nightly/images -v "/srv/che-nightly/instance":/opt/che:rw -e "CHE_ENV_FILE=/srv/che-nightly/instance/config/che.env" -e "CHE_CONTAINER_ROOT=/data" -e "CHE_ENVIRONMENT=production" -e "CHE_CONFIG=/srv/che-nightly/instance" -e "CHE_INSTANCE=/srv/che-nightly/instance" -e "CHE_REPO=off" --entrypoint=/usr/bin/puppet eclipse/che-init:nightly apply --modulepath /etc/puppet/modules/ /etc/puppet/manifests/ --show_diff >> "/data/cli.log"
DEBUG: docker_run
Notice: Compiled catalog for f265e5278a13.us-west-2.compute.internal in environment production in 0.20 seconds
Notice: /Stage[main]/Che/File[/opt/che/config/che.env]/content:
--- /opt/che/config/che.env
+++ /tmp/puppet-file20170121-1-1bfu4r0
@@ -21,7 +21,7 @@
CHE_ENVIRONMENT_FILE=che.env
CHE_ENV_FILE=/srv/che-nightly/instance/config/che.env
CHE_FORMAL_PRODUCT_NAME=Eclipse Che
-CHE_HOST=172.31.33.155
+CHE_HOST=ec2-......us-west-2.compute.amazonaws.com
CHE_HOST_BACKUP=/srv/che-nightly/backup
CHE_HOST_COMPOSE_FILE=docker-compose.yml
CHE_HOST_CONFIG=/srv/che-nightly
@@ -44,11 +44,12 @@
CHE_SERVER_CONTAINER_NAME=che
CHE_VERSION=nightly
CHE_VERSION_FILE=che.ver.do_not_modify
+CHE_DOCKER_PRIVILEGED=true
CHE_CONFIG=/srv/che-nightly/instance
CHE_INSTANCE=/srv/che-nightly/instance

-CHE_IP=172.31.33.155
+CHE_IP=ec2-......us-west-2.compute.amazonaws.com
CHE_PORT=8080
CHE_LOGS_DIR=/logs
#DOCKER_HOST=tcp://localhost:2375

Notice: /Stage[main]/Che/File[/opt/che/config/che.env]/content: content changed '{md5}0d18895b7b3d8a941e874b927a792185' to '{md5}0ac8ec5953a397eb8dfae1651dfeaafe'
Notice: Applied catalog in 0.09 seconds
INFO: (che config): Customizing docker-compose for running in a container
INFO: (che start): Preflight checks
DEBUG: port_open
port 8080 (http): [AVAILABLE]
DEBUG: port_open

INFO: (che start): Starting containers...
docker_compose --file="/data/instance/docker-compose-container.yml" -p="che" up -d >> "/data/cli.log" 2>&1
DEBUG: docker_compose
DEBUG: docker_run
Creating che
docker inspect -f '{{.Id}}' che
INFO: (che start): Services booting...
INFO: (che start): Server logs at "docker logs -f che"
DEBUG: docker_compose
DEBUG: docker_run
DEBUG: Container with id e584bcf2a029 is matching che service
DEBUG: Running state of container e584bcf2a029 is true
/usr/bin/curl "-I -k 172.31.33.155:8080/api/ -s -o /dev/null --write-out %{http_code}"
000
sleep 2
/usr/bin/curl "-I -k 172.31.33.155:8080/api/ -s -o /dev/null --write-out %{http_code}"
200
DEBUG: docker_compose
DEBUG: docker_run
DEBUG: Container with id e584bcf2a029 is matching che service
DEBUG: Running state of container e584bcf2a029 is true
/usr/bin/curl "-I -k 172.31.33.155:8080/api/ -s -o /dev/null --write-out %{http_code}"
200
DEBUG: is_initialized
DEBUG: docker_run
DEBUG: is_docker_for_mac
INFO: (che start): Booted and reachable
DEBUG: is_initialized
INFO: (che start): Ver: nightly
INFO: (che start): Use: http://ec2-.....us-west-2.compute.amazonaws.com:8080
INFO: (che start): API: http://ec2-......us-west-2.compute.amazonaws.com:8080/swagger
`

[TylerJewell]

@emvau - Matthias, thanks for taking the time to post an issue. We just with 5.0.1 released a new set of file system watchers. They are dynamic and require tuning. I'm going to ask one of the engineers to investigate this and to either confirm it as a bug or something that requires performance tuning.

[TylerJewell]

@dkuleshov @vparfonov - FYI for investigation.

[emvau]

Thanks for the fast reaction!

Some more info: the affected file tree consists of a lot of files (e.g. node_modules) with about 1,2 gigabytes of size and file depth up to 6. Another file tree holding only a few files reacts very well.
So I guess, the update of the file tree should be restricted only to the directory where the file operation took place - if possible.

[TylerJewell]

The update of the tree today is restricted to the single tree - but the amount of processing is a function of the size of the tree and type of project type, which may layer in additional analysis such as for Java, detecting modules, packages, and JARs.

[dkuleshov]

There is an optimization error in synchronization/update of project tree in cases when we have huge number of file, this is not a direct relative https://github.com/eclipse/che/issues/3467 but should solve the issue as well.

[ghost]

@emvau an investigation is in progress. We expect a few PRs that should dramatically improve both server and client when it comes to handling projects.

[dkuleshov]

https://github.com/eclipse/che/issues/4221 is created to fix this and similar issues

[TylerJewell]

We are testing fixes that will resolve this and some other issues. We will issue a bug fix as soon as this branch is merged - probably within a week.

https://github.com/eclipse/che/tree/che%233891