This Bugzilla instance is a read-only archive of historic NetBeans bug reports. To report a bug in NetBeans please follow the project's instructions for reporting issues.

Bug 184344 - Does "Checking For External Changes" affect parse for CND projects due to I/O concurrency?
Summary: Does "Checking For External Changes" affect parse for CND projects due to I/O...
Status: RESOLVED INVALID
Alias: None
Product: platform
Classification: Unclassified
Component: Filesystems (show other bugs)
Version: 6.x
Hardware: All All
: P2 normal (vote)
Assignee: Vladimir Voskresensky
URL:
Keywords: PERFORMANCE
Depends on:
Blocks:
 
Reported: 2010-04-16 10:13 UTC by Vladimir Voskresensky
Modified: 2010-04-20 09:24 UTC (History)
2 users (show)

See Also:
Issue Type: DEFECT
Exception Reporter:

Attachments
suspteded, but checking (8.42 KB, image/png)
2010-04-19 13:14 UTC, Vladimir Voskresensky 		Details
Add an attachment (proposed patch, testcase, etc.)

Note You need to log in before you can comment on or make changes to this bug.
Description Vladimir Voskresensky 2010-04-16 10:13:33 UTC 
We have removed "Scanning..." for CND projects and now new feature is making the same issues.

- I have started IDE with clean userdir
- opened big project (ACE_TAO) which takes some time to parse
- while project is parsed I switched to other work and from time to time I check if parsing is finished by switching to IDE and back
- all my switches to IDE force "Checking For External Changes" check again and again (what for???)
- this checks make again concurrency on I/O with parsing

That results in the slowdown of our parsing + the messages in log[1].
Please, do something with this often and expensive I/O checks. Previously IDE somehow worked without that checks an our users were absolutely fine to wait 3 secs when newly created external file appears in Files view. Now this checks are often and sometimes takes minutes.

[1]
WARNING [org.netbeans.modules.masterfs.filebasedfs.utils.FileChangedManager]: Too much time (1 602 ms) spend touching /net/d-espb04-127-81/export/devarea/osprojects/ACE_TAO_Solaris/ACE_wrappers/TAO/orbsvcs/tests/Notify/lib/Filter_Command.cpp
 === Stopping parser queue stopwatch /usr/include:       187778 ms
=== Starting parser queue stopwatch ACE68
 === Stopping parser queue stopwatch /usr/include:       196195 ms
=== Starting parser queue stopwatch ACE68
WARNING [org.netbeans.modules.masterfs.filebasedfs.utils.FileChangedManager]: Too much time (586 ms) spend touching /net/d-espb04-127-81/export/devarea/osprojects/ACE_TAO_Solaris/ACE_wrappers/build/TAO/tests/Timed_Buffered_Oneways/testC.h
WARNING [org.netbeans.modules.masterfs.filebasedfs.utils.FileChangedManager]: Too much time (3 323 ms) spend touching /net/d-espb04-127-81/export/devarea/osprojects/ACE_TAO_Solaris/ACE_wrappers/TAO/TAO_IDL/driver/drv_preproc.cpp
 === Stopping parser queue stopwatch /usr/sfw/include/c++/3.4.3:         224553 ms
=== Starting parser queue stopwatch ACE68
WARNING [org.netbeans.modules.masterfs.filebasedfs.utils.FileChangedManager]: Too much time (8 144 ms) spend touching /net/d-espb04-127-81/export/devarea/osprojects/ACE_TAO_Solaris/ACE_wrappers/ACEXML/tests/NamespaceSupport_Test.cpp
WARNING [org.netbeans.modules.masterfs.filebasedfs.utils.FileChangedManager]: Too much time (3 196 ms) spend touching /net/d-espb04-127-81/export/devarea/osprojects/ACE_TAO_Solaris/ACE_wrappers/ace/Registry_Name_Space.h
WARNING [org.netbeans.modules.masterfs.filebasedfs.utils.FileChangedManager]: Too much time (583 ms) spend touching /net/d-espb04-127-81/export/devarea/osprojects/ACE_TAO_Solaris/ACE_wrappers/build/TAO/tests/Bug_3163_Regression/testC.cpp
WARNING [org.netbeans.modules.masterfs.filebasedfs.utils.FileChangedManager]: Too much time (653 ms) spend touching /net/d-espb04-127-81/export/devarea/osprojects/ACE_TAO_Solaris/ACE_wrappers/TAO/tao/Strategies/DIOP_Acceptor.cpp
WARNING [org.netbeans.modules.masterfs.filebasedfs.utils.FileChangedManager]: Too much time (504 ms) spend touching /net/d-espb04-127-81/export/devarea/osprojects/ACE_TAO_Solaris/ACE_wrappers/TAO/TAO_IDL/include/ast_union_fwd.h
WARNING [org.netbeans.modules.masterfs.filebasedfs.utils.FileChangedManager]: Too much time (1 212 ms) spend touching /net/d-espb04-127-81/export/devarea/osprojects/ACE_TAO_Solaris/ACE_wrappers/build/TAO/docs/tutorials/Quoter/RTCORBA/DistributorS.h
 === Stopping parser queue stopwatch /usr/include:       275675 ms
=== Starting parser queue stopwatch ACE68
 === Stopping parser queue stopwatch /usr/include:       275684 ms
=== Starting parser queue stopwatch ACE68
 === Stopping parser queue stopwatch /usr/include:       275696 ms
=== Starting parser queue stopwatch ACE68
WARNING [org.netbeans.modules.masterfs.filebasedfs.utils.FileChangedManager]: Too much time (4 195 ms) spend touching /net/d-espb04-127-81/export/devarea/osprojects/ACE_TAO_Solaris/ACE_wrappers/TAO/orbsvcs/DevGuideExamples/EventServices/RTEC_Federated/EchoEventSupplier_i.h
 === Stopping parser queue stopwatch /usr/include:       286331 ms
=== Starting parser queue stopwatch ACE68
WARNING [org.netbeans.modules.masterfs.filebasedfs.utils.FileChangedManager]: Too much time (3 787 ms) spend touching /net/d-espb04-127-81/export/devarea/osprojects/ACE_TAO_Solaris/ACE_wrappers/build/TAO/orbsvcs/tests/Bug_2800_Regression/TestC.inl
WARNING [org.netbeans.modules.masterfs.filebasedfs.utils.FileChangedManager]: Too much time (877 ms) spend touching /net/d-espb04-127-81/export/devarea/osprojects/ACE_TAO_Solaris/ACE_wrappers/TAO/tests/Big_Reply/Big_Reply_i.cpp
WARNING [org.netbeans.modules.masterfs.filebasedfs.utils.FileChangedManager]: Too much time (3 500 ms) spend touching /net/d-espb04-127-81/export/devarea/osprojects/ACE_TAO_Solaris/ACE_wrappers/build/TAO/orbsvcs/tests/Event/Basic
WARNING [org.netbeans.modules.masterfs.filebasedfs.utils.FileChangedManager]: Too much time (2 495 ms) spend touching /net/d-espb04-127-81/export/devarea/osprojects/ACE_TAO_Solaris/ACE_wrappers/TAO/tests/POA/Default_Servant2/File_i.cpp
WARNING [org.netbeans.modules.masterfs.filebasedfs.utils.FileChangedManager]: Too much time (1 292 ms) spend touching /net/d-espb04-127-81/export/devarea/osprojects/ACE_TAO_Solaris/ACE_wrappers/build/TAO/orbsvcs/examples/Notify/ThreadPool
WARNING [org.netbeans.modules.masterfs.filebasedfs.utils.FileChangedManager]: Too much time (985 ms) spend touching /net/d-espb04-127-81/export/devarea/osprojects/ACE_TAO_Solaris/ACE_wrappers/TAO/tao/PortableServer/Collocated_Arguments_Converter.cpp
WARNING [org.netbeans.modules.masterfs.filebasedfs.utils.FileChangedManager]: Too much time (2 201 ms) spend touching /net/d-espb04-127-81/export/devarea/osprojects/ACE_TAO_Solaris/ACE_wrappers/build/TAO/tests/RTCORBA/Activate_Object_Multiple_ORBs/testC.h
WARNING [org.netbeans.modules.masterfs.filebasedfs.utils.FileChangedManager]: Too much time (808 ms) spend touching /net/d-espb04-127-81/export/devarea/osprojects/ACE_TAO_Solaris/ACE_wrappers/TAO/tao/GIOP_Message_Generator_Parser.h
WARNING [org.netbeans.modules.masterfs.filebasedfs.utils.FileChangedManager]: Too much time (699 ms) spend touching /net/d-espb04-127-81/export/devarea/osprojects/ACE_TAO_Solaris/ACE_wrappers/build/TAO/tests/IOR_Endpoint_Hostnames/bogusS.inl
WARNING [org.netbeans.modules.masterfs.filebasedfs.utils.FileChangedManager]: Too much time (1 232 ms) spend touching /net/d-espb04-127-81/export/devarea/osprojects/ACE_TAO_Solaris/ACE_wrappers/build/TAO/tao/PI/InvalidSlotC.cpp
WARNING [org.netbeans.modules.masterfs.filebasedfs.utils.FileChangedManager]: Too much time (1 783 ms) spend touching /net/d-espb04-127-81/export/devarea/osprojects/ACE_TAO_Solaris/ACE_wrappers/TAO/orbsvcs/tests
WARNING [org.netbeans.modules.masterfs.filebasedfs.utils.FileChangedManager]: Too much time (647 ms) spend touching /net/d-espb04-127-81/export/devarea/osprojects/ACE_TAO_Solaris/ACE_wrappers/TAO/orbsvcs/orbsvcs/CosEvent/CEC_TypedSupplierAdmin.h
WARNING [org.netbeans.modules.masterfs.filebasedfs.utils.FileChangedManager]: Too much time (602 ms) spend touching /net/d-espb04-127-81/export/devarea/osprojects/ACE_TAO_Solaris/ACE_wrappers/build/TAO/tests/Oneways_Invoking_Twoways/TestS.cpp
WARNING [org.netbeans.modules.masterfs.filebasedfs.utils.FileChangedManager]: Too much time (5 244 ms) spend touching /net/d-espb04-127-81/export/devarea/osprojects/ACE_TAO_Solaris/ACE_wrappers/build/TAO/performance-tests/Latency/Thread_Per_Connection/TestC.cpp
WARNING [org.netbeans.modules.masterfs.filebasedfs.utils.FileChangedManager]: Too much time (1 509 ms) spend touching /net/d-espb04-127-81/export/devarea/osprojects/ACE_TAO_Solaris/ACE_wrappers/TAO/tests/CodeSets/libs
WARNING [org.netbeans.modules.masterfs.filebasedfs.utils.FileChangedManager]: Too much time (2 074 ms) spend touching /net/d-espb04-127-81/export/devarea/osprojects/ACE_TAO_Solaris/ACE_wrappers/TAO/tao/GIOP_Message_Generator_Parser_11.h
WARNING [org.netbeans.core.TimableEventQueue]: too much time in AWT thread null
WARNING [org.netbeans.modules.masterfs.filebasedfs.utils.FileChangedManager]: Too much time (1 959 ms) spend touching /net/d-espb04-127-81/export/devarea/osprojects/ACE_TAO_Solaris/ACE_wrappers/TAO/orbsvcs/tests/AVStreams/Multicast_Full_Profile/ftp.h
 === Stopping parser queue stopwatch /usr/include:       389828 ms
=== Starting parser queue stopwatch ACE68
WARNING [org.netbeans.modules.masterfs.filebasedfs.utils.FileChangedManager]: Too much time (2 494 ms) spend touching /net/d-espb04-127-81/export/devarea/osprojects/ACE_TAO_Solaris/ACE_wrappers/TAO/TAO_IDL/be_include/be_visitor_root/root_sh.h
Comment 1 Jaroslav Tulach 2010-04-16 10:24:41 UTC 
This is no new "feature" it is with NetBeans since 4.0. I've just added progress indicator recently.

Since 6.9 the parsing API started to use addRecursiveListener, but as far as I understand, the module is disabled in CND only version.

You mention "were absolutely fine to wait 3 secs when newly created external file appears in Files view". I interpret that your users are in fact doing external changes and want the IDE to notice them. This is exactly what the code in question does. Disabling it will not make your users happy.

What shall be the next steps?
Comment 2 Vladimir Voskresensky 2010-04-16 15:50:37 UTC 
(In reply to comment #1)
> This is no new "feature" it is with NetBeans since 4.0. I've just added
> progress indicator recently.
Are use sure Up-to-date check was previously done on each "gain" focus immediately?
May be because it wasn't so visible - it wasn't so annoying when IDE did something in background?

> 
> Since 6.9 the parsing API started to use addRecursiveListener, but as far as I
> understand, the module is disabled in CND only version.
It is not disabled, it is not used on CND side => no "Scanning", because no ClassPaths from our side.

And we do not use recursiveListeners as well:
$ find cnd* -name "*.java" -exec egrep -n "addRecursiveListener" {} \;

I have tried it once and addRecursiveListener call took 5-15 minutes to finish (I attached to Z: folder on Windows box which was physically part of disk on remote Linux box).

> 
> You mention "were absolutely fine to wait 3 secs when newly created external
> file appears in Files view". I interpret that your users are in fact doing
> external changes and want the IDE to notice them. This is exactly what the code
> in question does. Disabling it will not make your users happy.
You are right + We need FileEvents mechanism, because we use own Indexing infrastructure (instead of slow Indexing API)

> 
> What shall be the next steps?
I see some problems here:
- progress is shown too often and takes rather long time
- looks like focus/unfocus/focus/unfocus/focus put several tasks in queue, that's why I see: 2 minutes, 20 sec, 10 sec progress bars one after another.

+
cancel didn't work as well(issue #184350), will check how it helped.
Comment 3 Jaroslav Tulach 2010-04-16 16:17:55 UTC 
FileUtil.refreshAll() was called on each focus gained for ages, but recursive listener makes the check longer.

Re. "5-15 minutes on Z: drive": How long it would take parsing the sources then? I hope not less than attaching the listener. Btw. this was the reason I made the attach cancellable: http://bits.netbeans.org/dev/javadoc/org-openide-filesystems/apichanges.html#addRecursiveListenerStop - the idea is to stop after 1000 folders and tell user that now the refresh will only be manual (not implemented so far).

Do you need reliable "FileSystem Events"? Even for files which are not displayed in the UI? Then you need not only FileUtil.refreshAll(), but also recursive listener (or hold all FileObjects for your files in memory). In spite how ineffective recursive listener is, it shall be much more effective than holding all FileObjects.

As soon as bug 184219 is integrated, use logging: -J-Dorg.netbeans.core.ui.focus.level=FINE to see what is going on. It is possible that there may be new refresh request waiting in the queue while one is in process. But only one, not more.
Comment 4 Vladimir Voskresensky 2010-04-16 18:56:55 UTC 
(In reply to comment #3)
> FileUtil.refreshAll() was called on each focus gained for ages, but recursive
> listener makes the check longer.
> 
> Re. "5-15 minutes on Z: drive": How long it would take parsing the sources
> then? I hope not less than attaching the listener. Btw. this was the reason I
> made the attach cancellable:
> http://bits.netbeans.org/dev/javadoc/org-openide-filesystems/apichanges.html#addRecursiveListenerStop
> - the idea is to stop after 1000 folders and tell user that now the refresh
> will only be manual (not implemented so far).
I experimented with recursive listeners to achieve "one FS listener". 
Wanted to use it for invalidating some parts of file-related caches, not full cache. Probably I can try it again.


> 
> Do you need reliable "FileSystem Events"? Even for files which are not
> displayed in the UI? Then you need not only FileUtil.refreshAll(), but also
> recursive listener (or hold all FileObjects for your files in memory). In spite
> how ineffective recursive listener is, it shall be much more effective than
> holding all FileObjects.
We listen on Folders FileObjects. Probably I can try it again for listening under source roots.

> 
> As soon as bug 184219 is integrated, use logging:
> -J-Dorg.netbeans.core.ui.focus.level=FINE to see what is going on. It is
> possible that there may be new refresh request waiting in the queue while one
> is in process. But only one, not more.
Probably "progress" bar makes here bad thing.
User switch to IDE, sees "Checking" => something is not finished => let's switch to other work and will change next time.
next time all repeats. The issue here is that user doesn't understand the consequences of not-yet-finished job.
Thanks to "Scanning...": nothing works until it finishes; navigator is empty, Go To doesn't work, debugger can not be started.
=> the same interpolation of user expectation to this activity in user mind.
Probably we need to hide it from users
Comment 5 Jaroslav Tulach 2010-04-16 19:33:50 UTC 
Maybe it works! For few days I am trying to design "I/O load" counter and maybe I succeeded. Maybe the WARNINGs above are caused by wrong logging. It shall not complain about slow File.exists() when running in the idleIO mode. Fixed in
http://hg.netbeans.org/core-main/rev/77ef1c05f55b

The remaining question is whether the messages were really only false warnings (in such case perfect, idle I/O mode really works), or if they slow down some important activity. I can imagine that those who react to events from the "Checking For External Changes" are also in idle I/O mode, which may not make them happy.

Vladimir, check it as soon as my changesets propagates. Also I'd suggest you to think up some more appropriate subject of this bug.
Comment 6 Jaroslav Tulach 2010-04-19 10:20:23 UTC 
Related effort is tracked as bug 184430.
Comment 7 Jaroslav Tulach 2010-04-19 10:57:21 UTC 
Vladimir please find that the slow down of CND parsing due to "Checking For External Changes" is close to zero and then close as invalid. In case it will not be as low, reassign back to me.
Comment 8 Vladimir Voskresensky 2010-04-19 13:12:20 UTC 
Jarda, what I see:
Checking for external changes appear with "suspended" message, but progress bar is growing => what does "suspended" mean?
Comment 9 Vladimir Voskresensky 2010-04-19 13:14:23 UTC 
Created attachment 97620 [details]
suspteded, but checking
Comment 10 Vladimir Voskresensky 2010-04-19 13:15:12 UTC 
after that next check + next check again (because I took screen shots? :-) )
Comment 11 Vladimir Voskresensky 2010-04-19 17:10:03 UTC 
I can not prove slowness due to "external check" process => close it
Comment 12 Jaroslav Tulach 2010-04-20 04:45:48 UTC 
"Suspended" means that the detected I/O load of the system is high and the "refreshSlow" task is waiting. Sometimes the computed I/O load can temporarily drop even parsing (in Java, as well in C++, I guess) is in progress. Then the "refreshSlow" task progresses a bit. The impact on overall parsing shall be close to zero. Should it be a problem, we can improve the way system realizes there is an I/O activity (reading from FileObject.getInputStream comes to my mind).

I am glad to see the issue is marked resolved for now.
Comment 13 Vladimir Voskresensky 2010-04-20 09:24:34 UTC 
(In reply to comment #12)
> "Suspended" means that the detected I/O load of the system is high and the
> "refreshSlow" task is waiting. Sometimes the computed I/O load can temporarily
> drop even parsing (in Java, as well in C++, I guess) is in progress. Then the
> "refreshSlow" task progresses a bit. The impact on overall parsing shall be
> close to zero. 
I see. Thanks.

> Should it be a problem, we can improve the way system realizes
> there is an I/O activity (reading from FileObject.getInputStream comes to my
> mind).
> 
> I am glad to see the issue is marked resolved for now.
I have checked timings and want to record that it doesn't slow down parsing:
-- With Check Ext Changes warm:
 === Stopping parser queue stopwatch ACE68:      333385 ms
-- No checks (warm) (-J-Dnetbeans.indexing.noFileRefresh=true)
 === Stopping parser queue stopwatch ACE68:      338199 ms