Re-importing gradle projects takes several minutes

Answered
Avatar
Tomerarazy
Created

This only started about 2 months ago and it's been driving me crazy.

We have a project with quite a lot of modules but re-import use to take 10-15 sec', but now it takes 5+ minutes, I've tried looking at the logs but I can't find anything useful there.

Ubuntu 18.04

IntelliJ 2019.2.3

Votes

1

Share

9 comments
Avatar
Tomerarazy
Created

Idea.log

2019-10-30 15:52:04,991 [104414891] INFO - s.plugins.gradle.GradleManager - Instructing gradle to use java from /usr/lib/jvm/jdk-11.0.2
2019-10-30 15:52:04,993 [104414893] INFO - s.plugins.gradle.GradleManager - Instructing gradle to use java from /usr/lib/jvm/jdk-11.0.2
2019-10-30 15:52:05,024 [104414924] INFO - xecution.GradleExecutionHelper - Passing command-line args to Gradle Tooling API: -Didea.sync.active=true -Didea.resolveSourceSetDependencies=true --init-script /tmp/ijinit.gradle
2019-10-30 15:52:06,496 [104416396] INFO - rationStore.ComponentStoreImpl - Saving appVcsApplicationSettings took 15 ms
2019-10-30 15:52:06,519 [104416419] INFO - rationStore.ComponentStoreImpl - Saving Module: 'crl8-modules.crl8-bookkeeper-integration.main'ExternalSystem took 16 ms
2019-10-30 15:52:06,548 [104416448] INFO - rationStore.ComponentStoreImpl - Saving Module: 'crl8-modules.crl8-common-persistence.test'ExternalFacetManager took 17 ms
2019-10-30 15:52:06,587 [104416487] INFO - rationStore.ComponentStoreImpl - Saving Module: 'crl8-modules.crl8-dispatcher-integration.test'ExternalFacetManager took 17 ms
2019-10-30 15:52:06,694 [104416594] INFO - rationStore.ComponentStoreImpl - Saving Module: 'crl8-modules.crl8-pricing.test'ExternalSystem took 11 ms
2019-10-30 15:52:06,748 [104416648] INFO - rationStore.ComponentStoreImpl - Saving Module: 'crl8-modules.crl8-violation-manager-module.test'TestModuleProperties took 17 ms
2019-10-30 15:52:06,830 [104416730] INFO - rationStore.ComponentStoreImpl - Saving Module: 'crl8-prometheus.test'ExternalSystem took 15 ms
2019-10-30 15:52:06,843 [104416743] INFO - mponents.impl.stores.StoreUtil - saveProjectsAndApp took 373 ms
2019-10-30 15:55:12,608 [104602508] INFO - mponents.impl.stores.StoreUtil - saveProjectsAndApp took 210 ms
2019-10-30 15:55:24,943 [104614843] INFO - rationStore.ComponentStoreImpl - Saving Module: 'crl8-modules.crl8-common-entities'ExternalSystem took 13 ms
2019-10-30 15:55:25,086 [104614986] INFO - mponents.impl.stores.StoreUtil - saveProjectsAndApp took 214 ms
2019-10-30 15:55:35,818 [104625718] INFO - rationStore.ComponentStoreImpl - Saving Module: 'crl8-modules.crl8-bookkeeper.main'ExternalFacetManager took 28 ms
2019-10-30 15:55:35,972 [104625872] INFO - mponents.impl.stores.StoreUtil - saveProjectsAndApp took 266 ms
2019-10-30 15:55:52,798 [104642698] INFO - rationStore.ComponentStoreImpl - Saving Module: 'crl8-modules.crl8-bookkeeper-module.test'ExternalFacetManager took 13 ms
2019-10-30 15:55:52,937 [104642837] INFO - mponents.impl.stores.StoreUtil - saveProjectsAndApp took 161 ms
2019-10-30 15:55:59,564 [104649464] INFO - rationStore.ComponentStoreImpl - Saving Project '/home/tomer/dev/crl8/trading-platform/crl8-prometheus' crl8-prometheusRunManager took 11 ms
2019-10-30 15:55:59,564 [104649464] INFO - mponents.impl.stores.StoreUtil - saveProjectsAndApp took 175 ms
2019-10-30 15:57:35,164 [104745064] INFO - rationStore.ComponentStoreImpl - Saving Module: 'crl8-modules.crl8-portfolio-manager.main'ExternalSystem took 13 ms
2019-10-30 15:57:35,251 [104745151] INFO - mponents.impl.stores.StoreUtil - saveProjectsAndApp took 212 ms
2019-10-30 15:57:39,061 [104748961] INFO - rationStore.ComponentStoreImpl - Saving Module: 'crl8-modules.crl8-bookkeeper-integration.main'ExternalFacetManager took 11 ms
2019-10-30 15:57:39,207 [104749107] INFO - mponents.impl.stores.StoreUtil - saveProjectsAndApp took 204 ms
2019-10-30 15:57:56,804 [104766704] INFO - mponents.impl.stores.StoreUtil - saveProjectsAndApp took 185 ms
2019-10-30 15:58:03,867 [104773767] INFO - System.util.ExternalSystemUtil - External project [/home/tomer/dev/crl8/trading-platform/crl8-modules] resolution task executed in 358878 ms.
2019-10-30 15:58:04,101 [104774001] INFO - ge.ExternalProjectsDataStorage - Save external projects data in 247 ms
2019-10-30 15:58:04,138 [104774038] INFO - mponents.impl.stores.StoreUtil - saveProjectsAndApp took 453 ms
2019-10-30 15:58:04,245 [104774145] INFO - rationStore.ComponentStoreImpl - Saving Module: 'crl8-modules.crl8-pricing.main'ExternalFacetManager took 19 ms
2019-10-30 15:58:04,288 [104774188] INFO - rationStore.ComponentStoreImpl - Saving Module: 'crl8-modules.crl8-trades-manager.test'ExternalFacetManager took 12 ms
2019-10-30 15:58:04,625 [104774525] INFO - ge.ExternalProjectsDataStorage - Save external projects data in 318 ms
2019-10-30 15:58:04,646 [104774546] INFO - mponents.impl.stores.StoreUtil - saveProjectsAndApp took 508 ms
2019-10-30 15:58:05,925 [104775825] INFO - pl.ProjectRootManagerComponent - project roots have changed
2019-10-30 15:58:06,024 [104775924] INFO - .diagnostic.PerformanceWatcher - Pushing properties took 19ms; general responsiveness: ok; EDT responsiveness: ok
2019-10-30 15:58:06,363 [104776263] INFO - .diagnostic.PerformanceWatcher - Indexable file iteration took 339ms; general responsiveness: ok; EDT responsiveness: ok
2019-10-30 15:58:06,901 [104776801] INFO - pl.projectlevelman.NewMappings - Mapped Roots: 1
2019-10-30 15:58:10,657 [104780557] INFO - mponents.impl.stores.StoreUtil - saveProjectsAndApp took 281 ms

0
Avatar
Tomerarazy
Created

Gradle daemon log

15:52:05.048 [DEBUG] [org.gradle.internal.remote.internal.inet.TcpIncomingConnector] Accepted connection from /127.0.0.1:49628 to /127.0.0.1:38329.
15:52:05.078 [DEBUG] [org.gradle.launcher.daemon.server.SynchronizedDispatchConnection] thread 53: received class org.gradle.launcher.daemon.protocol.Build
15:52:05.078 [DEBUG] [org.gradle.launcher.daemon.server.DefaultDaemonConnection] thread 53: Received non-IO message from client: Build{id=9eed6bfb-4724-4027-9450-9564c7be20c8, currentDir=/home/tomer/dev/crl8/trading-platform/crl8-modules}
15:52:05.078 [INFO] [org.gradle.launcher.daemon.server.DefaultIncomingConnectionHandler] Received command: Build{id=9eed6bfb-4724-4027-9450-9564c7be20c8, currentDir=/home/tomer/dev/crl8/trading-platform/crl8-modules}.
15:52:05.079 [DEBUG] [org.gradle.launcher.daemon.server.DefaultIncomingConnectionHandler] Starting executing command: Build{id=9eed6bfb-4724-4027-9450-9564c7be20c8, currentDir=/home/tomer/dev/crl8/trading-platform/crl8-modules} with connection: socket connection from /127.0.0.1:38329 to /127.0.0.1:49628.
15:52:05.080 [ERROR] [org.gradle.launcher.daemon.server.DaemonStateCoordinator] Command execution: started DaemonCommandExecution[command = Build{id=9eed6bfb-4724-4027-9450-9564c7be20c8, currentDir=/home/tomer/dev/crl8/trading-platform/crl8-modules}, connection = DefaultDaemonConnection: socket connection from /127.0.0.1:38329 to /127.0.0.1:49628] after 4.0 minutes of idle
15:52:05.080 [INFO] [org.gradle.launcher.daemon.server.DaemonRegistryUpdater] Marking the daemon as busy, address: [c1d92c07-ab2e-42d7-a119-ded227309796 port:38329, addresses:[/0:0:0:0:0:0:0:1%lo, /127.0.0.1]]
15:52:05.080 [DEBUG] [org.gradle.launcher.daemon.registry.PersistentDaemonRegistry] Marking busy by address: [c1d92c07-ab2e-42d7-a119-ded227309796 port:38329, addresses:[/0:0:0:0:0:0:0:1%lo, /127.0.0.1]]
15:52:05.080 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire exclusive lock on daemon addresses registry.
15:52:05.080 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired on daemon addresses registry.
15:52:05.081 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
15:52:05.081 [DEBUG] [org.gradle.launcher.daemon.server.DaemonStateCoordinator] resetting idle timer
15:52:05.081 [DEBUG] [org.gradle.launcher.daemon.server.DaemonStateCoordinator] daemon is running. Sleeping until state changes.
15:52:05.082 [INFO] [org.gradle.launcher.daemon.server.exec.StartBuildOrRespondWithBusy] Daemon is about to start building Build{id=9eed6bfb-4724-4027-9450-9564c7be20c8, currentDir=/home/tomer/dev/crl8/trading-platform/crl8-modules}. Dispatching build started information...
15:52:05.082 [DEBUG] [org.gradle.launcher.daemon.server.SynchronizedDispatchConnection] thread 55: dispatching class org.gradle.launcher.daemon.protocol.BuildStarted
15:52:05.083 [DEBUG] [org.gradle.launcher.daemon.server.exec.EstablishBuildEnvironment] Configuring env variables: {PATH=/home/tomer/bin:/home/tomer/.local/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin, INVOCATION_ID=9200740e4b9e48c68b0150610a851890, XAUTHORITY=/run/user/1000/gdm/Xauthority, LC_MEASUREMENT=en_US.UTF-8, LC_TELEPHONE=en_US.UTF-8, XMODIFIERS=@im=ibus, GDMSESSION=unity, XDG_DATA_DIRS=/usr/share/unity:/usr/local/share/:/usr/share/:/var/lib/snapd/desktop, MANDATORY_PATH=/usr/share/gconf/unity.mandatory.path, LC_TIME=en_US.UTF-8, PAPERSIZE=letter, TEXTDOMAINDIR=/usr/share/locale/, GTK_IM_MODULE=ibus, DBUS_SESSION_BUS_ADDRESS=unix:path=/run/user/1000/bus, DEFAULTS_PATH=/usr/share/gconf/unity.default.path, XDG_CURRENT_DESKTOP=Unity:Unity7:ubuntu, JOURNAL_STREAM=9:43336, QT4_IM_MODULE=xim, LC_PAPER=en_US.UTF-8, USERNAME=tomer, LOGNAME=tomer, PWD=/home/tomer, MANAGERPID=2121, IM_CONFIG_PHASE=2, S_COLORS=auto, SHELL=/bin/bash, LC_ADDRESS=en_US.UTF-8, UNITY_HAS_3D_SUPPORT=true, GIO_LAUNCHED_DESKTOP_FILE=/home/tomer/.local/share/applications/jetbrains-idea-ce.desktop, GTK2_MODULES=overlay-scrollbar, OLDPWD=/home/tomer/.local/share/JetBrains/Toolbox/apps/IDEA-C/ch-0/192.6817.14/bin, GNOME_DESKTOP_SESSION_ID=this-is-deprecated, GTK_MODULES=gail:atk-bridge:unity-gtk-module, CLUTTER_IM_MODULE=xim, TEXTDOMAIN=im-config, COMPIZ_BIN_PATH=/usr/bin/, XDG_SESSION_DESKTOP=unity, SSH_AGENT_LAUNCHER=gnome-keyring, SHLVL=1, LC_IDENTIFICATION=en_US.UTF-8, LC_MONETARY=en_US.UTF-8, COMPIZ_CONFIG_PROFILE=ubuntu, QT_IM_MODULE=ibus, XDG_CONFIG_DIRS=/etc/xdg/xdg-unity:/etc/xdg, LANG=en_US.UTF-8, XDG_SESSION_TYPE=x11, DISPLAY=:0, UNITY_DEFAULT_PROFILE=unity, LC_NAME=en_US.UTF-8, _=/usr/bin/dbus-update-activation-environment, DESKTOP_SESSION=unity, GPG_AGENT_INFO=/run/user/1000/gnupg/S.gpg-agent:0:1, USER=tomer, GTK_CSD=0, XDG_MENU_PREFIX=gnome-, GIO_LAUNCHED_DESKTOP_FILE_PID=1357, QT_ACCESSIBILITY=1, WINDOWPATH=2, LC_NUMERIC=en_US.UTF-8, SSH_AUTH_SOCK=/run/user/1000/keyring/ssh, GNOME_SESSION_XDG_SESSION_PATH=, QT_QPA_PLATFORMTHEME=appmenu-qt5, LD_PRELOAD=libgtk3-nocsd.so.0, XDG_RUNTIME_DIR=/run/user/1000, HOME=/home/tomer}
15:52:05.085 [DEBUG] [org.gradle.launcher.daemon.server.exec.LogToClient] About to start relaying all logs to the client via the connection.
15:52:05.085 [INFO] [org.gradle.launcher.daemon.server.exec.LogToClient] The client will now receive all logging from the daemon (pid: 6548). The daemon log file: /home/tomer/.gradle/daemon/5.4.1/daemon-6548.out.log
15:52:05.088 [DEBUG] [org.gradle.launcher.daemon.server.SynchronizedDispatchConnection] thread 53: received class org.gradle.launcher.daemon.protocol.CloseInput
15:52:05.089 [DEBUG] [org.gradle.launcher.daemon.server.DefaultDaemonConnection] thread 53: Received IO message from client: org.gradle.launcher.daemon.protocol.CloseInput@17443c26
15:52:05.092 [INFO] [org.gradle.launcher.daemon.server.exec.LogAndCheckHealth] Starting 3rd build in daemon [uptime: 15 mins 7.123 secs, performance: 100%, non-heap usage: 31% of 268.4 MB]
15:52:05.092 [DEBUG] [org.gradle.launcher.daemon.server.exec.ExecuteBuild] The daemon has started executing the build.
15:52:05.093 [DEBUG] [org.gradle.launcher.daemon.server.exec.ExecuteBuild] Executing build with daemon context: DefaultDaemonContext[uid=d12ef486-b38f-4492-bae5-c8c9aaa4b09b,javaHome=/usr/lib/jvm/jdk-11.0.2,daemonRegistryDir=/home/tomer/.gradle/daemon,pid=6548,idleTimeout=10800000,priority=NORMAL,daemonOpts=--add-opens,java.base/java.util=ALL-UNNAMED,--add-opens,java.base/java.lang=ALL-UNNAMED,--add-opens,java.base/java.lang.invoke=ALL-UNNAMED,--add-opens,java.prefs/java.util.prefs=ALL-UNNAMED,-XX:MaxMetaspaceSize=256m,-XX:+HeapDumpOnOutOfMemoryError,-Xms256m,-Xmx512m,-Dfile.encoding=UTF-8,-Duser.country=US,-Duser.language=en,-Duser.variant]
15:52:05.112 [INFO] [org.gradle.launcher.daemon.server.exec.ForwardClientInput] Closing daemon's stdin at end of input.

CONFIGURE SUCCESSFUL in 5m 57s
15:58:02.434 [DEBUG] [org.gradle.launcher.daemon.server.SynchronizedDispatchConnection] thread 58: dispatching class org.gradle.launcher.daemon.protocol.BuildEvent
15:58:02.434 [DEBUG] [org.gradle.launcher.daemon.server.exec.ExecuteBuild] The daemon has finished executing the build.
15:58:02.445 [DEBUG] [org.gradle.launcher.daemon.server.DaemonStateCoordinator] daemon is running. Sleeping until state changes.
15:58:02.445 [DEBUG] [org.gradle.launcher.daemon.server.DaemonStateCoordinator] Command execution: finished waiting for DaemonCommandExecution[command = Build{id=9eed6bfb-4724-4027-9450-9564c7be20c8, currentDir=/home/tomer/dev/crl8/trading-platform/crl8-modules}, connection = DefaultDaemonConnection: socket connection from /127.0.0.1:38329 to /127.0.0.1:49628]. Result org.gradle.launcher.daemon.server.DaemonStateCoordinator@2b977302 with state Busy
15:58:02.445 [DEBUG] [org.gradle.launcher.daemon.server.DaemonStateCoordinator] Command execution: completed DaemonCommandExecution[command = Build{id=9eed6bfb-4724-4027-9450-9564c7be20c8, currentDir=/home/tomer/dev/crl8/trading-platform/crl8-modules}, connection = DefaultDaemonConnection: socket connection from /127.0.0.1:38329 to /127.0.0.1:49628]
15:58:02.445 [DEBUG] [org.gradle.launcher.daemon.server.DaemonStateCoordinator] resetting idle timer
15:58:02.445 [INFO] [org.gradle.launcher.daemon.server.DaemonRegistryUpdater] Marking the daemon as idle, address: [c1d92c07-ab2e-42d7-a119-ded227309796 port:38329, addresses:[/0:0:0:0:0:0:0:1%lo, /127.0.0.1]]
15:58:02.445 [DEBUG] [org.gradle.launcher.daemon.registry.PersistentDaemonRegistry] Marking busy by address: [c1d92c07-ab2e-42d7-a119-ded227309796 port:38329, addresses:[/0:0:0:0:0:0:0:1%lo, /127.0.0.1]]
15:58:02.445 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire exclusive lock on daemon addresses registry.
15:58:02.446 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired on daemon addresses registry.
15:58:02.446 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
15:58:02.446 [DEBUG] [org.gradle.launcher.daemon.server.DaemonStateCoordinator] daemon is running. Sleeping until state changes.
15:58:02.446 [DEBUG] [org.gradle.launcher.daemon.server.exec.ReturnResult] Daemon is dispatching the build result: Success[value=org.gradle.launcher.exec.BuildActionResult@783a413e]
15:58:02.446 [DEBUG] [org.gradle.launcher.daemon.server.SynchronizedDispatchConnection] thread 52: dispatching class org.gradle.launcher.daemon.protocol.Success
15:58:02.447 [DEBUG] [org.gradle.launcher.daemon.server.DefaultIncomingConnectionHandler] Finishing executing command: Build{id=9eed6bfb-4724-4027-9450-9564c7be20c8, currentDir=/home/tomer/dev/crl8/trading-platform/crl8-modules}
15:58:02.538 [DEBUG] [org.gradle.launcher.daemon.server.SynchronizedDispatchConnection] thread 53: received class org.gradle.launcher.daemon.protocol.Finished
15:58:02.538 [DEBUG] [org.gradle.launcher.daemon.server.DefaultDaemonConnection] thread 53: Received non-IO message from client: org.gradle.launcher.daemon.protocol.Finished@5cee8824
15:58:02.538 [DEBUG] [org.gradle.internal.remote.internal.inet.SocketConnection] Discarding EOFException: java.io.EOFException
15:58:02.538 [DEBUG] [org.gradle.launcher.daemon.server.SynchronizedDispatchConnection] thread 53: received null
15:58:02.538 [DEBUG] [org.gradle.launcher.daemon.server.DefaultDaemonConnection] thread 53: Received end-of-input from client.
15:58:02.540 [DEBUG] [org.gradle.launcher.daemon.server.DefaultIncomingConnectionHandler] Received finished message: null
15:58:02.541 [DEBUG] [org.gradle.launcher.daemon.server.SynchronizedDispatchConnection] thread 52: stopping connection
15:58:02.542 [DEBUG] [org.gradle.launcher.daemon.server.SynchronizedDispatchConnection] thread 52: stopping connection
15:58:08.188 [DEBUG] [org.gradle.launcher.daemon.server.Daemon] DaemonExpirationPeriodicCheck running
15:58:08.188 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
15:58:08.188 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired on daemon addresses registry.
15:58:08.188 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
15:58:08.189 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
15:58:08.189 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired on daemon addresses registry.
15:58:08.189 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
15:58:18.189 [DEBUG] [org.gradle.launcher.daemon.server.Daemon] DaemonExpirationPeriodicCheck running
15:58:18.189 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
15:58:18.190 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired on daemon addresses registry.
15:58:18.190 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
15:58:18.191 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
15:58:18.191 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired on daemon addresses registry.
15:58:18.192 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
15:58:18.192 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
15:58:18.193 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired on daemon addresses registry.
15:58:18.193 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
15:58:28.189 [DEBUG] [org.gradle.launcher.daemon.server.Daemon] DaemonExpirationPeriodicCheck running
15:58:28.190 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
15:58:28.190 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired on daemon addresses registry.
15:58:28.191 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
15:58:28.191 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
15:58:28.191 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired on daemon addresses registry.
15:58:28.192 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
15:58:28.192 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
15:58:28.192 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired on daemon addresses registry.
15:58:28.193 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
15:58:38.189 [DEBUG] [org.gradle.launcher.daemon.server.Daemon] DaemonExpirationPeriodicCheck running
15:58:38.190 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
15:58:38.190 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired on daemon addresses registry.
15:58:38.191 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
15:58:38.191 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
15:58:38.192 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired on daemon addresses registry.
15:58:38.192 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
15:58:38.192 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Waiting to acquire shared lock on daemon addresses registry.
15:58:38.193 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Lock acquired on daemon addresses registry.
15:58:38.193 [DEBUG] [org.gradle.cache.internal.DefaultFileLockManager] Releasing lock on daemon addresses registry.
0
Avatar
Andrey Dernov
Created

Do you have antivirus/firewall? How long does Gradle build itself take (from command line and from IDE)? Do you have network mounts?

Try if it makes a difference using different Gradle and/or JDK version for Gradle.

Please add 

#org.jetbrains.plugins.gradle.service.project.data.PerformanceTraceDataService
org.jetbrains.plugins.gradle.service.project.data.PerformanceTraceDataService

lines into Help | Debug Log Settings... dialog reproduce the problem and provide idea.log. For uploading you can use ftp://ftp.intellij.net/.uploads / https://uploads.services.jetbrains.com or any file sharing service.

0
Avatar
Tomerarazy
Created

Hi Andrey

No AV/Firewall, no network mounts.

I've tried different Gradle version but there is no difference, same with JDK version.

The build itself is fine, takes about 2 min' with the IDEA (clean build) and about the same time from the command line - It's a big project (10 projects) so 2 min' is expected for a clean build.

I've uploaded the idea.log with the debug settings you've suggested using https://uploads.services.jetbrains.com/ but i'm not sure what's the address of that file.

The file name is: idea-debug-gradle-issue.log , But since I'm not sure this worked I'm also pasting the log it self here.

It seems to me that the critical issue is this line:

2019-10-31 12:08:18,377 [2077667] INFO - System.util.ExternalSystemUtil - External project [/home/tomer/dev/crl8/trading-platform/crl8-modules] resolution task executed in 337648 ms.

And this is the full log:

2019-10-31 12:02:39,768 [1739058] INFO - lij.diagnostic.DebugLogManager - Set DEBUG for the following categories: org.jetbrains.plugins.gradle.service.project.data.PerformanceTraceDataService 
2019-10-31 12:02:40,492 [1739782] INFO - rationStore.ComponentStoreImpl - Saving Project '/home/tomer/dev/crl8/trading-platform/crl8-modules' crl8-modulesRunManager took 11 ms 
2019-10-31 12:02:40,492 [1739782] INFO - mponents.impl.stores.StoreUtil - saveProjectsAndApp took 396 ms 
2019-10-31 12:02:40,732 [1740022] INFO - s.plugins.gradle.GradleManager - Instructing gradle to use java from /usr/lib/jvm/jdk-11.0.2 
2019-10-31 12:02:40,732 [1740022] INFO - s.plugins.gradle.GradleManager - Instructing gradle to use java from /usr/lib/jvm/jdk-11.0.2 
2019-10-31 12:02:40,753 [1740043] INFO - xecution.GradleExecutionHelper - Passing command-line args to Gradle Tooling API: -Didea.sync.active=true -Didea.resolveSourceSetDependencies=true --init-script /tmp/ijinit.gradle 
2019-10-31 12:02:42,668 [1741958] INFO - rationStore.ComponentStoreImpl - Saving Module: 'crl8-modules.crl8-common-utilities.main'ExternalFacetManager took 11 ms 
2019-10-31 12:02:42,699 [1741989] INFO - rationStore.ComponentStoreImpl - Saving Module: 'crl8-modules.crl8-common-persistence.main'ExternalFacetManager took 12 ms 
2019-10-31 12:02:42,711 [1742001] INFO - rationStore.ComponentStoreImpl - Saving Module: 'crl8-modules.crl8-common-utilities.test'ExternalFacetManager took 11 ms 
2019-10-31 12:02:42,734 [1742024] INFO - rationStore.ComponentStoreImpl - Saving Module: 'crl8-modules.crl8-common.test'ExternalFacetManager took 12 ms 
2019-10-31 12:02:42,789 [1742079] INFO - rationStore.ComponentStoreImpl - Saving Module: 'crl8-modules.crl8-dispatcher.main'ExternalFacetManager took 12 ms 
2019-10-31 12:02:42,815 [1742105] INFO - rationStore.ComponentStoreImpl - Saving Module: 'crl8-modules.crl8-dispatcher.test'ExternalFacetManager took 18 ms 
2019-10-31 12:02:42,862 [1742152] INFO - rationStore.ComponentStoreImpl - Saving Module: 'crl8-modules.crl8-filtering-module.main'ExternalFacetManager took 11 ms 
2019-10-31 12:02:42,914 [1742204] INFO - rationStore.ComponentStoreImpl - Saving Module: 'crl8-modules.crl8-orchestrator-module.test'ExternalFacetManager took 11 ms 
2019-10-31 12:02:43,025 [1742315] INFO - rationStore.ComponentStoreImpl - Saving Module: 'crl8-modules.crl8-trades-manager-module.main'ExternalFacetManager took 11 ms 
2019-10-31 12:02:43,045 [1742335] INFO - rationStore.ComponentStoreImpl - Saving Module: 'crl8-modules.crl8-trades-manager-integration.test'ExternalFacetManager took 11 ms 
2019-10-31 12:02:43,073 [1742363] INFO - rationStore.ComponentStoreImpl - Saving Module: 'crl8-modules.crl8-violation-manager-integration.test'ExternalFacetManager took 16 ms 
2019-10-31 12:02:43,127 [1742417] INFO - rationStore.ComponentStoreImpl - Saving Module: 'crl8-modules.test'ExternalFacetManager took 11 ms 
2019-10-31 12:02:43,224 [1742514] INFO - rationStore.ComponentStoreImpl - Saving Project '/home/tomer/dev/crl8/trading-platform/crl8-modules' crl8-modulesRunManager took 16 ms, libraryTable took 15 ms 
2019-10-31 12:02:43,225 [1742515] INFO - mponents.impl.stores.StoreUtil - saveProjectsAndApp took 862 ms 
2019-10-31 12:03:01,716 [1761006] INFO - rationStore.ComponentStoreImpl - Saving appFindSettings took 13 ms 
2019-10-31 12:03:01,784 [1761074] INFO - rationStore.ComponentStoreImpl - Saving Module: 'crl8-modules.crl8-bookkeeper.test'ExternalFacetManager took 24 ms 
2019-10-31 12:03:01,863 [1761153] INFO - rationStore.ComponentStoreImpl - Saving Module: 'crl8-modules.crl8-filtering-module.test'TestModuleProperties took 11 ms 
2019-10-31 12:03:02,014 [1761304] INFO - mponents.impl.stores.StoreUtil - saveProjectsAndApp took 354 ms 
2019-10-31 12:08:18,377 [2077667] INFO - System.util.ExternalSystemUtil - External project [/home/tomer/dev/crl8/trading-platform/crl8-modules] resolution task executed in 337648 ms. 
2019-10-31 12:08:18,628 [2077918] INFO - rationStore.ComponentStoreImpl - Saving appWindowManager took 11 ms 
2019-10-31 12:08:18,666 [2077956] INFO - rationStore.ComponentStoreImpl - Saving Module: 'crl8-modules.crl8-common-entities.test'ExternalSystem took 14 ms 
2019-10-31 12:08:19,241 [2078531] INFO - ge.ExternalProjectsDataStorage - Save external projects data in 356 ms 
2019-10-31 12:08:19,293 [2078583] INFO - rationStore.ComponentStoreImpl - Saving Project '/home/tomer/dev/crl8/trading-platform/crl8-modules' crl8-modulesRunManager took 11 ms, TaskManager took 11 ms 
2019-10-31 12:08:19,303 [2078593] INFO - mponents.impl.stores.StoreUtil - saveProjectsAndApp took 730 ms 
2019-10-31 12:08:21,008 [2080298] INFO - pl.ProjectRootManagerComponent - project roots have changed 
2019-10-31 12:08:21,142 [2080432] INFO - .diagnostic.PerformanceWatcher - Pushing properties took 39ms; general responsiveness: ok; EDT responsiveness: ok 
2019-10-31 12:08:21,534 [2080824] INFO - .diagnostic.PerformanceWatcher - Indexable file iteration took 392ms; general responsiveness: ok; EDT responsiveness: ok 
2019-10-31 12:08:21,956 [2081246] INFO - pl.projectlevelman.NewMappings - Mapped Roots: 1

I've also encountered those errors during one of the tests, I'm not sure if it's related or not:

2019-10-31 11:27:35,859 [2364036] INFO - ide.actions.ShowFilePathAction - Nautilus-Share-Message: 11:27:26.792: Called "net usershare info" but it failed: 'net usershar
e' returned error 255: mkdir failed on directory /var/run/samba/msg.lock: Permission denied
net usershare: cannot open usershare directory /var/lib/samba/usershares. Error No such file or directory
Please ask your system administrator to enable user sharing.


Timed out 
2019-10-31 11:29:26,795 [2474972] WARN - n.process.BaseOSProcessHandler - Process hasn't generated any output for a long time.
If it's a long-running mostly idle daemon process, consider overriding OSProcessHandler#readerOptions with 'BaseOutputReader.Options.forMostlySilentProcess()' to reduce CPU usage.
Command line: nautilus /home/tomer/.IdeaIC2019.2/system/log/idea.log 
java.lang.Throwable: Process creation:
at com.intellij.execution.process.BaseOSProcessHandler.<init>(BaseOSProcessHandler.java:33)
at com.intellij.execution.process.OSProcessHandler.<init>(OSProcessHandler.java:151)
at com.intellij.execution.process.OSProcessHandler.<init>(OSProcessHandler.java:38)
at com.intellij.execution.process.CapturingProcessHandler.<init>(CapturingProcessHandler.java:21)
at com.intellij.ide.actions.ShowFilePathAction.lambda$spawn$9(ShowFilePathAction.java:329)
at com.intellij.openapi.application.impl.ApplicationImpl$1.run(ApplicationImpl.java:294)
at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at java.base/java.lang.Thread.run(Thread.java:834)

 

Thanks!

 

0
Avatar
Andrey Dernov
Created

You need to have this exact line in Debug lLog settings dialog: 

#org.jetbrains.plugins.gradle.service.project.data.PerformanceTraceDataService

with the hash in front. I see you only added the

org.jetbrains.plugins.gradle.service.project.data.PerformanceTraceDataService

one. Please add these two lines reproduce and re-upload the log. Thanks.

0
Avatar
Tomerarazy
Created

Oops, thought the line with the hash at front was commented out line :)

The correct file is here: http://s000.tinyupload.com/index.php?file_id=22535873795952348664

0
Avatar
Andrey Dernov
Created

Sorry for a delayed reply.

>Gradle data obtained: 374198 ms.

This is a time took for Gradle daemon to process and give data to IDE. With such numbers I'm not sure that this regression could be caused by the IDE update. 

Did you always use separate modules per Gradle source set option? It could introduce some overhead in case of very large projects but this overhead is still not compared with the numbers you mention, looking in logs - at max it could add a minute.

Could it be that the build itself has changed? Can you compare it with the IDE version where you did not experience this problem?

Could it be that dependencies resolve and downloading that takes time? E.g. a slow network or DNS resolutions. You can e.g. try enabling an Offline mode in Gradle tool window and try re-import.


In general we plan to redesign current project model for external system projects like Gradle, Maven. So costs like

>Get model IdeaProject : 155137 ms.

could be almost eliminated. But this is a scope of 2020.X versions.

0
Avatar
Tomerarazy
Created

Hi Andrey, thanks again for the detailed response.

It seems that switching to Offline mode "fixes" the issue and reduce the re-import time to a few seconds.

Unfortunately a lot of our dependencies are being served from a remote repositories so this is not a viable option for me for most of the time :/

Any suggestions on how to investigate this issue?

0
Avatar
Andrey Dernov
Created

To see what exactly takes the time you can by taking jstack thread dumps of java IDE process and external Gradle daemon process which runs the Gradle: https://intellij-support.jetbrains.com/hc/en-us/articles/206544899 to see what exactly IDE and Gradle daemon processes are doing. You can find the `GradleDaemon` process from command line using ps utility e.g. ps auxww | grep gradle to find out the PID and take several jstack dumps of it at the moment of execution.

Such issues are usually caused by Antivirus/firewall or network (dns) misconfiguration - when process takes long time to resolve the host when is trying to connect.

0

Please sign in to leave a comment.